Skip to content

Commit

Permalink
[cc/metrics] Report a diagnostic metric to understand delayed frames.
Browse files Browse the repository at this point in the history 
Report the offset between the actual presentation timestamp, and the
expected frame-deadline (i.e. vsync time). We will have this metric for
a shortwhile to validate our assumption that the permissive deadline we
currently use to detect 'missed deadline' frames are correct.

BUG=1064574

Change-Id: Ib5a9c4085deb4140ab037dd897a1a76a65cd67d9
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2237657
Reviewed-by: Stephen Chenney <schenney@chromium.org>
Reviewed-by: Behdad Bakhshinategh <behdadb@chromium.org>
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#777080}
  • Loading branch information
@sadrulhc
sadrulhc authored and Commit Bot committed Jun 10, 2020
1 parent 62a04f1 commit a2fffed
Show file tree
Hide file tree
Showing 5 changed files with 56 additions and 31 deletions.
36 changes: 26 additions & 10 deletions cc/metrics/compositor_frame_reporter.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -212,19 +212,34 @@ std::string GetEventLatencyHistogramBaseName(
is_scroll ? event_metrics.GetScrollTypeName() : nullptr});
}

base::TimeTicks ComputeSafeDeadlineForFrame(const viz::BeginFrameArgs& args) {
return args.frame_time + (args.interval * 1.5);
}

void ReportOffsetBetweenDeadlineAndPresentationTime(
const viz::BeginFrameArgs& args,
base::TimeTicks presentation_time) {
const base::TimeTicks strict_deadline = args.frame_time + args.interval;
const base::TimeDelta offset = presentation_time - strict_deadline;
// |strict_deadline| and |presentation_time| should normally be pretty close.
// Measure how close they are.
UMA_HISTOGRAM_CUSTOM_TIMES(
"CompositorLatency.Diagnostic.PresentationTimeDeltaFromDeadline", offset,
base::TimeDelta::FromMilliseconds(1),
base::TimeDelta::FromMilliseconds(32), /*bucket_count=*/16);
}

} // namespace

CompositorFrameReporter::CompositorFrameReporter(
const ActiveTrackers& active_trackers,
const viz::BeginFrameId& id,
const base::TimeTicks frame_deadline,
const viz::BeginFrameArgs& args,
LatencyUkmReporter* latency_ukm_reporter,
bool should_report_metrics)
: frame_id_(id),
should_report_metrics_(should_report_metrics),
: should_report_metrics_(should_report_metrics),
args_(args),
active_trackers_(active_trackers),
latency_ukm_reporter_(latency_ukm_reporter),
frame_deadline_(frame_deadline) {}
latency_ukm_reporter_(latency_ukm_reporter) {}

std::unique_ptr<CompositorFrameReporter>
CompositorFrameReporter::CopyReporterAtBeginImplStage() const {
Expand All @@ -235,8 +250,7 @@ CompositorFrameReporter::CopyReporterAtBeginImplStage() const {
return nullptr;
}
auto new_reporter = std::make_unique<CompositorFrameReporter>(
active_trackers_, frame_id_, frame_deadline_, latency_ukm_reporter_,
should_report_metrics_);
active_trackers_, args_, latency_ukm_reporter_, should_report_metrics_);
new_reporter->did_finish_impl_frame_ = did_finish_impl_frame_;
new_reporter->impl_frame_finish_time_ = impl_frame_finish_time_;
new_reporter->main_frame_abort_time_ = main_frame_abort_time_;
Expand Down Expand Up @@ -357,7 +371,9 @@ void CompositorFrameReporter::TerminateReporter() {
case FrameTerminationStatus::kPresentedFrame:
EnableReportType(FrameReportType::kNonDroppedFrame);
termination_status_str = "presented_frame";
if (frame_deadline_ < frame_termination_time_)
ReportOffsetBetweenDeadlineAndPresentationTime(args_,
frame_termination_time_);
if (ComputeSafeDeadlineForFrame(args_) < frame_termination_time_)
EnableReportType(FrameReportType::kMissedDeadlineFrame);
break;
case FrameTerminationStatus::kDidNotPresentFrame:
Expand Down Expand Up @@ -706,7 +722,7 @@ void CompositorFrameReporter::ReportCompositorLatencyTraceEvents(
const auto trace_id = TRACE_ID_LOCAL(this);
TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
"cc,benchmark", "PipelineReporter", trace_id,
stage_history_.front().start_time, "frame_id", frame_id_.ToString());
stage_history_.front().start_time, "frame_id", args_.frame_id.ToString());

// The trace-viewer cannot seem to handle a single child-event that has the
// same start/end timestamps as the parent-event. So avoid adding the
Expand Down
10 changes: 5 additions & 5 deletions cc/metrics/compositor_frame_reporter.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -128,8 +128,7 @@ class CC_EXPORT CompositorFrameReporter {
std::bitset<static_cast<size_t>(FrameSequenceTrackerType::kMaxType)>;

CompositorFrameReporter(const ActiveTrackers& active_trackers,
const viz::BeginFrameId& id,
const base::TimeTicks frame_deadline,
const viz::BeginFrameArgs& args,
LatencyUkmReporter* latency_ukm_reporter,
bool should_report_metrics);
~CompositorFrameReporter();
Expand All @@ -140,8 +139,6 @@ class CC_EXPORT CompositorFrameReporter {

std::unique_ptr<CompositorFrameReporter> CopyReporterAtBeginImplStage() const;

const viz::BeginFrameId frame_id_;

// Note that the started stage may be reported to UMA. If the histogram is
// intended to be reported then the histograms.xml file must be updated too.
void StartStage(StageType stage_type, base::TimeTicks start_time);
Expand Down Expand Up @@ -184,6 +181,8 @@ class CC_EXPORT CompositorFrameReporter {
tick_clock_ = tick_clock;
}

const viz::BeginFrameId& frame_id() const { return args_.frame_id; }

private:
void TerminateReporter();
void EndCurrentStage(base::TimeTicks end_time);
Expand Down Expand Up @@ -234,6 +233,7 @@ class CC_EXPORT CompositorFrameReporter {
base::TimeTicks Now() const;

const bool should_report_metrics_;
const viz::BeginFrameArgs args_;

StageData current_stage_;

Expand Down Expand Up @@ -272,7 +272,6 @@ class CC_EXPORT CompositorFrameReporter {
// The time that work on Impl frame is finished. It's only valid if the
// reporter is in a stage other than begin impl frame.
base::TimeTicks impl_frame_finish_time_;
base::TimeTicks frame_deadline_;

// The timestamp of when the frame was marked as not having produced a frame
// (through a call to DidNotProduceFrame()).
Expand All @@ -282,6 +281,7 @@ class CC_EXPORT CompositorFrameReporter {

const base::TickClock* tick_clock_ = base::DefaultTickClock::GetInstance();
};

} // namespace cc

#endif // CC_METRICS_COMPOSITOR_FRAME_REPORTER_H_"
3 changes: 1 addition & 2 deletions cc/metrics/compositor_frame_reporter_unittest.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,8 +30,7 @@ class CompositorFrameReporterTest : public testing::Test {
CompositorFrameReporterTest()
: pipeline_reporter_(std::make_unique<CompositorFrameReporter>(
CompositorFrameReporter::ActiveTrackers(),
viz::BeginFrameId(),
base::TimeTicks() + base::TimeDelta::FromMilliseconds(16),
viz::BeginFrameArgs(),
nullptr,
/*should_report_metrics=*/true)) {
pipeline_reporter_->set_tick_clock(&test_tick_clock_);
Expand Down
27 changes: 13 additions & 14 deletions cc/metrics/compositor_frame_reporting_controller.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -68,8 +68,8 @@ void CompositorFrameReportingController::WillBeginImplFrame(
reporter->did_not_produce_frame_time());
}
auto reporter = std::make_unique<CompositorFrameReporter>(
active_trackers_, args.frame_id, args.frame_time + (args.interval * 1.5),
latency_ukm_reporter_.get(), should_report_metrics_);
active_trackers_, args, latency_ukm_reporter_.get(),
should_report_metrics_);
reporter->set_tick_clock(tick_clock_);
reporter->StartStage(StageType::kBeginImplFrameToSendBeginMainFrame,
begin_time);
Expand All @@ -83,7 +83,7 @@ void CompositorFrameReportingController::WillBeginMainFrame(
// C++20 feature.
DCHECK_NE(reporters_[PipelineStage::kBeginMainFrame].get(),
reporters_[PipelineStage::kBeginImplFrame].get());
DCHECK_EQ(reporters_[PipelineStage::kBeginImplFrame]->frame_id_,
DCHECK_EQ(reporters_[PipelineStage::kBeginImplFrame]->frame_id(),
args.frame_id);
reporters_[PipelineStage::kBeginImplFrame]->StartStage(
StageType::kSendBeginMainFrameToCommit, Now());
Expand All @@ -94,8 +94,7 @@ void CompositorFrameReportingController::WillBeginMainFrame(
// beginMain frame before next BeginImplFrame (Not reached the ImplFrame
// deadline yet). So will start a new reporter at BeginMainFrame.
auto reporter = std::make_unique<CompositorFrameReporter>(
active_trackers_, args.frame_id,
args.frame_time + (args.interval * 1.5), latency_ukm_reporter_.get(),
active_trackers_, args, latency_ukm_reporter_.get(),
should_report_metrics_);
reporter->set_tick_clock(tick_clock_);
reporter->StartStage(StageType::kSendBeginMainFrameToCommit, Now());
Expand All @@ -107,7 +106,7 @@ void CompositorFrameReportingController::BeginMainFrameAborted(
const viz::BeginFrameId& id) {
auto& reporter = reporters_[PipelineStage::kBeginMainFrame];
DCHECK(reporter);
DCHECK_EQ(reporter->frame_id_, id);
DCHECK_EQ(reporter->frame_id(), id);
reporter->OnAbortBeginMainFrame(Now());
}

Expand Down Expand Up @@ -169,7 +168,7 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame(
// |impl_reporter| is guaranteed to be set, and |main_reporter| will not be
// set.
if (is_activated_frame_new) {
DCHECK_EQ(reporters_[PipelineStage::kActivate]->frame_id_,
DCHECK_EQ(reporters_[PipelineStage::kActivate]->frame_id(),
last_activated_frame_id);
// The reporter in activate state can be submitted
main_reporter = std::move(reporters_[PipelineStage::kActivate]);
Expand Down Expand Up @@ -220,7 +219,7 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame(
DCHECK(main_reporter);
// If there are impl events, there must be a reporter with
// |current_frame_id|.
DCHECK_EQ(main_reporter->frame_id_, current_frame_id);
DCHECK_EQ(main_reporter->frame_id(), current_frame_id);
events_metrics.main_event_metrics.reserve(
events_metrics.main_event_metrics.size() +
events_metrics.impl_event_metrics.size());
Expand Down Expand Up @@ -255,7 +254,7 @@ void CompositorFrameReportingController::DidNotProduceFrame(
const viz::BeginFrameId& id,
FrameSkippedReason skip_reason) {
for (auto& stage_reporter : reporters_) {
if (stage_reporter && stage_reporter->frame_id_ == id) {
if (stage_reporter && stage_reporter->frame_id() == id) {
// The reporter will be flagged and terminated when replaced by another
// reporter. The reporter is not terminated immediately here because it
// can still end up producing a frame afterwards. For example, if the
Expand All @@ -272,7 +271,7 @@ void CompositorFrameReportingController::DidNotProduceFrame(
void CompositorFrameReportingController::OnFinishImplFrame(
const viz::BeginFrameId& id) {
for (auto& reporter : reporters_) {
if (reporter && reporter->frame_id_ == id) {
if (reporter && reporter->frame_id() == id) {
reporter->OnFinishImplFrame(Now());
return;
}
Expand Down Expand Up @@ -356,15 +355,15 @@ bool CompositorFrameReportingController::CanSubmitImplFrame(
if (!reporters_[PipelineStage::kBeginImplFrame])
return false;
auto& reporter = reporters_[PipelineStage::kBeginImplFrame];
return (reporter->frame_id_ == id && reporter->did_finish_impl_frame());
return (reporter->frame_id() == id && reporter->did_finish_impl_frame());
}

bool CompositorFrameReportingController::CanSubmitMainFrame(
const viz::BeginFrameId& id) const {
if (!reporters_[PipelineStage::kBeginMainFrame])
return false;
auto& reporter = reporters_[PipelineStage::kBeginMainFrame];
return (reporter->frame_id_ == id && reporter->did_finish_impl_frame() &&
return (reporter->frame_id() == id && reporter->did_finish_impl_frame() &&
reporter->did_abort_main_frame());
}

Expand All @@ -373,9 +372,9 @@ CompositorFrameReportingController::RestoreReporterAtBeginImpl(
const viz::BeginFrameId& id) {
auto& main_reporter = reporters_[PipelineStage::kBeginMainFrame];
auto& commit_reporter = reporters_[PipelineStage::kCommit];
if (main_reporter && main_reporter->frame_id_ == id)
if (main_reporter && main_reporter->frame_id() == id)
return main_reporter->CopyReporterAtBeginImplStage();
if (commit_reporter && commit_reporter->frame_id_ == id)
if (commit_reporter && commit_reporter->frame_id() == id)
return commit_reporter->CopyReporterAtBeginImplStage();
return nullptr;
}
Expand Down
11 changes: 11 additions & 0 deletions tools/metrics/histograms/histograms.xml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -28402,6 +28402,17 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
</summary>
</histogram>

<histogram
name="CompositorLatency.Diagnostic.PresentationTimeDeltaFromDeadline"
units="ms" expires_after="M87">
<owner>behdadb@chromium.org</owner>
<owner>sadrul@chromium.org</owner>
<summary>
For the compositor pipeline, measures how far the presentation time of a
compositor frame is from the frame deadline (i.e. vsync time).
</summary>
</histogram>

<histogram base="true" name="CompositorLatency.DroppedFrame"
units="microseconds" expires_after="2021-01-31">
<owner>sadrul@chromium.org</owner>
Expand Down

0 comments on commit a2fffed

Please sign in to comment.