#include "cc/metrics/frame_sequence_tracker.h"
#include <algorithm>
#include <memory>
#include <string>
#include <utility>
#include "base/containers/contains.h"
#include "base/containers/cxx20_erase.h"
#include "base/functional/bind.h"
#include "base/logging.h"
#include "base/metrics/histogram.h"
#include "base/metrics/histogram_macros.h"
#include "base/notreached.h"
#include "base/trace_event/trace_event.h"
#include "base/trace_event/traced_value.h"
#include "components/viz/common/frame_sinks/begin_frame_args.h"
#include "components/viz/common/quads/compositor_frame_metadata.h"
#include "ui/gfx/presentation_feedback.h"
#if DCHECK_IS_ON()
#define TRACKER_TRACE_STREAM frame_sequence_trace_
#define TRACKER_DCHECK_MSG \
" in " << GetFrameSequenceTrackerTypeName(this->type()) \
<< " tracker: " << frame_sequence_trace_.str() << " (" \
<< frame_sequence_trace_.str().size() << ")";
#else
#define TRACKER_TRACE_STREAM EAT_STREAM_PARAMETERS
#define TRACKER_DCHECK_MSG ""
#endif
namespace cc {
namespace {
constexpr char kTraceCategory[] =
"cc,benchmark," TRACE_DISABLED_BY_DEFAULT("devtools.timeline.frame");
}
using ThreadType = FrameInfo::SmoothEffectDrivingThread;
constexpr int kDebugStrMod = 1000;
const char* FrameSequenceTracker::GetFrameSequenceTrackerTypeName(
FrameSequenceTrackerType type) {
switch (type) {
case FrameSequenceTrackerType::kCompositorAnimation:
return "CompositorAnimation";
case FrameSequenceTrackerType::kMainThreadAnimation:
return "MainThreadAnimation";
case FrameSequenceTrackerType::kPinchZoom:
return "PinchZoom";
case FrameSequenceTrackerType::kRAF:
return "RAF";
case FrameSequenceTrackerType::kTouchScroll:
return "TouchScroll";
case FrameSequenceTrackerType::kVideo:
return "Video";
case FrameSequenceTrackerType::kWheelScroll:
return "WheelScroll";
case FrameSequenceTrackerType::kScrollbarScroll:
return "ScrollbarScroll";
case FrameSequenceTrackerType::kCustom:
return "Custom";
case FrameSequenceTrackerType::kCanvasAnimation:
return "CanvasAnimation";
case FrameSequenceTrackerType::kJSAnimation:
return "JSAnimation";
case FrameSequenceTrackerType::kSETMainThreadAnimation:
return "SETMainThreadAnimation";
case FrameSequenceTrackerType::kSETCompositorAnimation:
return "SETCompositorAnimation";
case FrameSequenceTrackerType::kMaxType:
return "";
}
}
FrameSequenceTracker::FrameSequenceTracker(FrameSequenceTrackerType type)
: custom_sequence_id_(-1),
metrics_(std::make_unique<FrameSequenceMetrics>(type)) {
DCHECK_LT(type, FrameSequenceTrackerType::kMaxType);
DCHECK(type != FrameSequenceTrackerType::kCustom);
TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
kTraceCategory, "TrackerValidation", TRACE_ID_LOCAL(this),
base::TimeTicks::Now(), "name", GetFrameSequenceTrackerTypeName(type));
}
FrameSequenceTracker::FrameSequenceTracker(
int custom_sequence_id,
FrameSequenceMetrics::CustomReporter custom_reporter)
: custom_sequence_id_(custom_sequence_id),
metrics_(std::make_unique<FrameSequenceMetrics>(
FrameSequenceTrackerType::kCustom)) {
DCHECK_GT(custom_sequence_id_, 0);
metrics_->SetCustomReporter(std::move(custom_reporter));
}
FrameSequenceTracker::~FrameSequenceTracker() {
TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP2(
kTraceCategory, "TrackerValidation", TRACE_ID_LOCAL(this),
base::TimeTicks::Now(), "aborted_main", aborted_main_frame_,
"no_damage_main", no_damage_draw_main_frames_);
CleanUp();
}
void FrameSequenceTracker::ScheduleTerminate() {
if (!is_inside_frame_ && last_submitted_frame_ == 0)
termination_status_ = TerminationStatus::kReadyForTermination;
else
termination_status_ = TerminationStatus::kScheduledForTermination;
}
void FrameSequenceTracker::ReportBeginImplFrame(
const viz::BeginFrameArgs& args) {
if (termination_status_ != TerminationStatus::kActive)
return;
if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
return;
TRACKER_TRACE_STREAM << "b(" << args.frame_id.sequence_number % kDebugStrMod
<< ")";
DCHECK(!is_inside_frame_) << TRACKER_DCHECK_MSG;
is_inside_frame_ = true;
#if DCHECK_IS_ON()
if (args.type == viz::BeginFrameArgs::NORMAL)
impl_frames_.insert(args.frame_id);
#endif
DCHECK_EQ(last_started_impl_sequence_, 0u) << TRACKER_DCHECK_MSG;
last_started_impl_sequence_ = args.frame_id.sequence_number;
if (reset_all_state_) {
begin_impl_frame_data_ = {};
begin_main_frame_data_ = {};
reset_all_state_ = false;
}
DCHECK(!frame_had_no_compositor_damage_) << TRACKER_DCHECK_MSG;
DCHECK(!compositor_frame_submitted_) << TRACKER_DCHECK_MSG;
UpdateTrackedFrameData(&begin_impl_frame_data_, args.frame_id.source_id,
args.frame_id.sequence_number,
args.frames_throttled_since_last);
impl_throughput().frames_expected +=
begin_impl_frame_data_.previous_sequence_delta;
if (first_frame_timestamp_.is_null())
first_frame_timestamp_ = args.frame_time;
}
void FrameSequenceTracker::ReportBeginMainFrame(
const viz::BeginFrameArgs& args) {
if (termination_status_ != TerminationStatus::kActive)
return;
if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
return;
TRACKER_TRACE_STREAM << "B("
<< begin_main_frame_data_.previous_sequence %
kDebugStrMod
<< "," << args.frame_id.sequence_number % kDebugStrMod
<< ")";
if (first_received_main_sequence_ &&
first_received_main_sequence_ > args.frame_id.sequence_number) {
return;
}
if (!first_received_main_sequence_ &&
ShouldIgnoreSequence(args.frame_id.sequence_number)) {
return;
}
#if DCHECK_IS_ON()
if (args.type == viz::BeginFrameArgs::NORMAL) {
DCHECK(impl_frames_.contains(args.frame_id)) << TRACKER_DCHECK_MSG;
}
#endif
last_processed_main_sequence_latency_ = 0;
pending_main_sequences_.push_back(args.frame_id.sequence_number);
UpdateTrackedFrameData(&begin_main_frame_data_, args.frame_id.source_id,
args.frame_id.sequence_number,
args.frames_throttled_since_last);
if (!first_received_main_sequence_ ||
first_received_main_sequence_ <= last_no_main_damage_sequence_) {
first_received_main_sequence_ = args.frame_id.sequence_number;
}
main_throughput().frames_expected +=
begin_main_frame_data_.previous_sequence_delta;
previous_begin_main_sequence_ = current_begin_main_sequence_;
current_begin_main_sequence_ = args.frame_id.sequence_number;
}
void FrameSequenceTracker::ReportMainFrameProcessed(
const viz::BeginFrameArgs& args) {
if (termination_status_ != TerminationStatus::kActive)
return;
if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
return;
TRACKER_TRACE_STREAM << "E(" << args.frame_id.sequence_number % kDebugStrMod
<< ")";
const bool previous_main_frame_submitted_or_no_damage =
previous_begin_main_sequence_ != 0 &&
(last_submitted_main_sequence_ == previous_begin_main_sequence_ ||
last_no_main_damage_sequence_ == previous_begin_main_sequence_);
if (last_processed_main_sequence_ != 0 &&
!had_impl_frame_submitted_between_commits_ &&
!previous_main_frame_submitted_or_no_damage) {
DCHECK_GE(main_throughput().frames_expected,
begin_main_frame_data_.previous_sequence_delta)
<< TRACKER_DCHECK_MSG;
main_throughput().frames_expected -=
begin_main_frame_data_.previous_sequence_delta;
last_no_main_damage_sequence_ = previous_begin_main_sequence_;
}
had_impl_frame_submitted_between_commits_ = false;
if (first_received_main_sequence_ &&
args.frame_id.sequence_number >= first_received_main_sequence_) {
DCHECK_EQ(last_processed_main_sequence_latency_, 0u) << TRACKER_DCHECK_MSG;
last_processed_main_sequence_ = args.frame_id.sequence_number;
last_processed_main_sequence_latency_ =
std::max(last_started_impl_sequence_, last_processed_impl_sequence_) -
args.frame_id.sequence_number;
}
}
void FrameSequenceTracker::ReportSubmitFrame(
uint32_t frame_token,
bool has_missing_content,
const viz::BeginFrameAck& ack,
const viz::BeginFrameArgs& origin_args) {
DCHECK_NE(termination_status_, TerminationStatus::kReadyForTermination);
const uint32_t frames_to_terminate_tracker = 3;
if (termination_status_ == TerminationStatus::kScheduledForTermination &&
last_submitted_frame_ != 0 &&
viz::FrameTokenGT(frame_token,
last_submitted_frame_ + frames_to_terminate_tracker)) {
termination_status_ = TerminationStatus::kReadyForTermination;
return;
}
if (ShouldIgnoreBeginFrameSource(ack.frame_id.source_id) ||
ShouldIgnoreSequence(ack.frame_id.sequence_number)) {
ignored_frame_tokens_.insert(frame_token);
return;
}
last_processed_impl_sequence_ = ack.frame_id.sequence_number;
if (first_submitted_frame_ == 0)
first_submitted_frame_ = frame_token;
last_submitted_frame_ = frame_token;
compositor_frame_submitted_ = true;
TRACKER_TRACE_STREAM << "s(" << frame_token % kDebugStrMod << ")";
had_impl_frame_submitted_between_commits_ = true;
metrics()->NotifySubmitForJankReporter(
FrameInfo::SmoothEffectDrivingThread::kCompositor, frame_token,
ack.frame_id.sequence_number);
const bool main_changes_after_sequence_started =
first_received_main_sequence_ &&
origin_args.frame_id.sequence_number >= first_received_main_sequence_;
const bool main_changes_include_new_changes =
last_submitted_main_sequence_ == 0 ||
origin_args.frame_id.sequence_number > last_submitted_main_sequence_;
const bool main_change_had_no_damage =
last_no_main_damage_sequence_ != 0 &&
origin_args.frame_id.sequence_number == last_no_main_damage_sequence_;
const bool origin_args_is_valid = origin_args.frame_id.sequence_number <=
begin_main_frame_data_.previous_sequence;
if (!ShouldIgnoreBeginFrameSource(origin_args.frame_id.source_id) &&
origin_args_is_valid) {
if (main_changes_after_sequence_started &&
main_changes_include_new_changes && !main_change_had_no_damage) {
submitted_frame_had_new_main_content_ = true;
TRACKER_TRACE_STREAM << "S("
<< origin_args.frame_id.sequence_number %
kDebugStrMod
<< ")";
metrics()->NotifySubmitForJankReporter(
FrameInfo::SmoothEffectDrivingThread::kMain, frame_token,
origin_args.frame_id.sequence_number);
last_submitted_main_sequence_ = origin_args.frame_id.sequence_number;
main_frames_.push_back(frame_token);
DCHECK_GE(main_throughput().frames_expected, main_frames_.size())
<< TRACKER_DCHECK_MSG;
}
}
if (has_missing_content) {
checkerboarding_.frames.push_back(frame_token);
}
}
void FrameSequenceTracker::ReportFrameEnd(
const viz::BeginFrameArgs& args,
const viz::BeginFrameArgs& main_args) {
DCHECK_NE(termination_status_, TerminationStatus::kReadyForTermination);
if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
return;
while (!pending_main_sequences_.empty() &&
pending_main_sequences_.front() <=
main_args.frame_id.sequence_number) {
pending_main_sequences_.pop_front();
}
TRACKER_TRACE_STREAM << "e(" << args.frame_id.sequence_number % kDebugStrMod
<< ","
<< main_args.frame_id.sequence_number % kDebugStrMod
<< ")";
bool should_ignore_sequence =
ShouldIgnoreSequence(args.frame_id.sequence_number);
if (reset_all_state_) {
begin_impl_frame_data_ = {};
begin_main_frame_data_ = {};
reset_all_state_ = false;
}
if (should_ignore_sequence) {
is_inside_frame_ = false;
return;
}
if (compositor_frame_submitted_ && submitted_frame_had_new_main_content_ &&
last_processed_main_sequence_latency_) {
main_throughput().frames_expected += last_processed_main_sequence_latency_;
}
if (frame_had_no_compositor_damage_ && !compositor_frame_submitted_) {
DCHECK_GT(impl_throughput().frames_expected, 0u) << TRACKER_DCHECK_MSG;
DCHECK_GT(impl_throughput().frames_expected,
impl_throughput().frames_produced)
<< TRACKER_DCHECK_MSG;
DCHECK_GE(impl_throughput().frames_produced,
impl_throughput().frames_ontime)
<< TRACKER_DCHECK_MSG;
--impl_throughput().frames_expected;
metrics()->NotifyNoUpdateForJankReporter(
FrameInfo::SmoothEffectDrivingThread::kCompositor,
args.frame_id.sequence_number, args.interval);
begin_impl_frame_data_.previous_sequence = 0;
}
if (termination_status_ == TerminationStatus::kScheduledForTermination &&
last_submitted_frame_ == 0)
termination_status_ = TerminationStatus::kReadyForTermination;
frame_had_no_compositor_damage_ = false;
compositor_frame_submitted_ = false;
submitted_frame_had_new_main_content_ = false;
last_processed_main_sequence_latency_ = 0;
DCHECK(is_inside_frame_) << TRACKER_DCHECK_MSG;
is_inside_frame_ = false;
DCHECK_EQ(last_started_impl_sequence_, last_processed_impl_sequence_)
<< TRACKER_DCHECK_MSG;
last_started_impl_sequence_ = 0;
}
void FrameSequenceTracker::ReportFramePresented(
uint32_t frame_token,
const gfx::PresentationFeedback& feedback) {
const bool submitted_frame_since_last_presentation = !!last_submitted_frame_;
const bool frame_token_acks_last_frame =
!viz::FrameTokenGT(last_submitted_frame_, frame_token);
if (last_submitted_frame_ && frame_token_acks_last_frame)
last_submitted_frame_ = 0;
if (termination_status_ == TerminationStatus::kScheduledForTermination &&
last_submitted_frame_ == 0 && !is_inside_frame_) {
termination_status_ = TerminationStatus::kReadyForTermination;
}
if (first_submitted_frame_ == 0 ||
viz::FrameTokenGT(first_submitted_frame_, frame_token)) {
return;
}
TRACKER_TRACE_STREAM << "P(" << frame_token % kDebugStrMod << ")";
base::EraseIf(ignored_frame_tokens_, [frame_token](const uint32_t& token) {
return viz::FrameTokenGT(frame_token, token);
});
if (ignored_frame_tokens_.contains(frame_token))
return;
const auto vsync_interval =
(feedback.interval.is_zero() ? viz::BeginFrameArgs::DefaultInterval()
: feedback.interval);
DCHECK(!vsync_interval.is_zero()) << TRACKER_DCHECK_MSG;
base::TimeTicks safe_deadline_for_frame =
last_frame_presentation_timestamp_ + vsync_interval * 1.5;
const bool was_presented = !feedback.failed();
if (was_presented && submitted_frame_since_last_presentation) {
if (!last_frame_presentation_timestamp_.is_null() &&
(safe_deadline_for_frame < feedback.timestamp)) {
DCHECK_LE(impl_throughput().frames_ontime,
impl_throughput().frames_produced)
<< TRACKER_DCHECK_MSG;
++impl_throughput().frames_ontime;
}
DCHECK_LT(impl_throughput().frames_produced,
impl_throughput().frames_expected)
<< TRACKER_DCHECK_MSG;
++impl_throughput().frames_produced;
if (metrics()->GetEffectiveThread() == ThreadType::kCompositor) {
metrics()->AdvanceTrace(feedback.timestamp);
}
metrics()->ComputeJank(FrameInfo::SmoothEffectDrivingThread::kCompositor,
frame_token, feedback.timestamp, vsync_interval);
}
if (was_presented) {
const unsigned size_before_erase = main_frames_.size();
while (!main_frames_.empty() &&
!viz::FrameTokenGT(main_frames_.front(), frame_token)) {
main_frames_.pop_front();
}
if (main_frames_.size() < size_before_erase) {
DCHECK_LT(main_throughput().frames_produced,
main_throughput().frames_expected)
<< TRACKER_DCHECK_MSG;
++main_throughput().frames_produced;
if (metrics()->GetEffectiveThread() == ThreadType::kMain) {
metrics()->AdvanceTrace(feedback.timestamp);
}
metrics()->ComputeJank(FrameInfo::SmoothEffectDrivingThread::kMain,
frame_token, feedback.timestamp, vsync_interval);
}
if (main_frames_.size() < size_before_erase) {
if (!last_frame_presentation_timestamp_.is_null() &&
(safe_deadline_for_frame < feedback.timestamp)) {
DCHECK_LE(main_throughput().frames_ontime,
main_throughput().frames_produced)
<< TRACKER_DCHECK_MSG;
++main_throughput().frames_ontime;
}
}
last_frame_presentation_timestamp_ = feedback.timestamp;
if (checkerboarding_.last_frame_had_checkerboarding) {
DCHECK(!checkerboarding_.last_frame_timestamp.is_null())
<< TRACKER_DCHECK_MSG;
DCHECK(!feedback.timestamp.is_null()) << TRACKER_DCHECK_MSG;
base::TimeDelta difference =
feedback.timestamp - checkerboarding_.last_frame_timestamp;
const auto& interval = feedback.interval.is_zero()
? viz::BeginFrameArgs::DefaultInterval()
: feedback.interval;
DCHECK(!interval.is_zero()) << TRACKER_DCHECK_MSG;
constexpr base::TimeDelta kEpsilon = base::Milliseconds(1);
int64_t frames = (difference + kEpsilon).IntDiv(interval);
metrics_->add_checkerboarded_frames(frames);
}
const bool frame_had_checkerboarding =
base::Contains(checkerboarding_.frames, frame_token);
checkerboarding_.last_frame_had_checkerboarding = frame_had_checkerboarding;
checkerboarding_.last_frame_timestamp = feedback.timestamp;
}
while (!checkerboarding_.frames.empty() &&
!viz::FrameTokenGT(checkerboarding_.frames.front(), frame_token)) {
checkerboarding_.frames.pop_front();
}
}
void FrameSequenceTracker::ReportImplFrameCausedNoDamage(
const viz::BeginFrameAck& ack) {
DCHECK_NE(termination_status_, TerminationStatus::kReadyForTermination);
if (ShouldIgnoreBeginFrameSource(ack.frame_id.source_id))
return;
TRACKER_TRACE_STREAM << "n(" << ack.frame_id.sequence_number % kDebugStrMod
<< ")";
if (ShouldIgnoreSequence(ack.frame_id.sequence_number))
return;
last_processed_impl_sequence_ = ack.frame_id.sequence_number;
DCHECK_EQ(begin_impl_frame_data_.previous_sequence,
ack.frame_id.sequence_number);
frame_had_no_compositor_damage_ = true;
}
void FrameSequenceTracker::ReportMainFrameCausedNoDamage(
const viz::BeginFrameArgs& args,
bool aborted) {
if (termination_status_ != TerminationStatus::kActive)
return;
if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
return;
TRACKER_TRACE_STREAM << "N("
<< begin_main_frame_data_.previous_sequence %
kDebugStrMod
<< "," << args.frame_id.sequence_number % kDebugStrMod
<< ")";
if (!first_received_main_sequence_ ||
first_received_main_sequence_ > args.frame_id.sequence_number) {
return;
}
if (last_no_main_damage_sequence_ == args.frame_id.sequence_number)
return;
auto initial_pending_size = pending_main_sequences_.size();
while (!pending_main_sequences_.empty() &&
pending_main_sequences_.front() <= args.frame_id.sequence_number) {
pending_main_sequences_.pop_front();
}
if (pending_main_sequences_.size() == initial_pending_size)
return;
if (aborted)
++aborted_main_frame_;
else
++no_damage_draw_main_frames_;
DCHECK_GT(main_throughput().frames_expected, 0u) << TRACKER_DCHECK_MSG;
DCHECK_GT(main_throughput().frames_expected,
main_throughput().frames_produced)
<< TRACKER_DCHECK_MSG;
DCHECK_GE(main_throughput().frames_produced, main_throughput().frames_ontime)
<< TRACKER_DCHECK_MSG;
last_no_main_damage_sequence_ = args.frame_id.sequence_number;
--main_throughput().frames_expected;
metrics()->NotifyNoUpdateForJankReporter(
FrameInfo::SmoothEffectDrivingThread::kMain,
args.frame_id.sequence_number, args.interval);
DCHECK_GE(main_throughput().frames_expected, main_frames_.size())
<< TRACKER_DCHECK_MSG;
if (begin_main_frame_data_.previous_sequence != 0) {
DCHECK_GE(begin_main_frame_data_.previous_sequence,
args.frame_id.sequence_number)
<< TRACKER_DCHECK_MSG;
}
begin_main_frame_data_.previous_sequence = 0;
}
void FrameSequenceTracker::PauseFrameProduction() {
TRACKER_TRACE_STREAM << 'R';
reset_all_state_ = true;
}
void FrameSequenceTracker::UpdateTrackedFrameData(
TrackedFrameData* frame_data,
uint64_t source_id,
uint64_t sequence_number,
uint64_t throttled_frame_count) {
if (frame_data->previous_sequence &&
frame_data->previous_source == source_id) {
uint32_t current_latency =
sequence_number - frame_data->previous_sequence - throttled_frame_count;
DCHECK_GT(current_latency, 0u) << TRACKER_DCHECK_MSG;
frame_data->previous_sequence_delta = current_latency;
} else {
frame_data->previous_sequence_delta = 1;
}
frame_data->previous_source = source_id;
frame_data->previous_sequence = sequence_number;
}
bool FrameSequenceTracker::ShouldIgnoreBeginFrameSource(
uint64_t source_id) const {
if (begin_impl_frame_data_.previous_source == 0)
return source_id == viz::BeginFrameArgs::kManualSourceId;
return source_id != begin_impl_frame_data_.previous_source;
}
bool FrameSequenceTracker::ShouldIgnoreSequence(
uint64_t sequence_number) const {
return sequence_number != begin_impl_frame_data_.previous_sequence;
}
bool FrameSequenceTracker::ShouldReportMetricsNow(
const viz::BeginFrameArgs& args) const {
return metrics_->HasEnoughDataForReporting() &&
!first_frame_timestamp_.is_null() &&
args.frame_time - first_frame_timestamp_ >= time_delta_to_report_;
}
std::unique_ptr<FrameSequenceMetrics> FrameSequenceTracker::TakeMetrics() {
return std::move(metrics_);
}
void FrameSequenceTracker::CleanUp() {
if (metrics_)
metrics_->ReportLeftoverData();
}
void FrameSequenceTracker::AddSortedFrame(const viz::BeginFrameArgs& args,
const FrameInfo& frame_info) {
if (metrics_)
metrics_->AddSortedFrame(args, frame_info);
}
FrameSequenceTracker::CheckerboardingData::CheckerboardingData() = default;
FrameSequenceTracker::CheckerboardingData::~CheckerboardingData() = default;
}