1 // Copyright 2019 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
5 #include "cc/metrics/compositor_frame_reporter.h"
12 #include "base/cpu_reduction_experiment.h"
13 #include "base/metrics/histogram_macros.h"
14 #include "base/notreached.h"
15 #include "base/ranges/algorithm.h"
16 #include "base/strings/strcat.h"
17 #include "base/strings/string_util.h"
18 #include "base/time/time.h"
19 #include "base/trace_event/trace_event.h"
20 #include "base/trace_event/trace_id_helper.h"
21 #include "base/trace_event/typed_macros.h"
22 #include "base/tracing/protos/chrome_track_event.pbzero.h"
23 #include "cc/base/rolling_time_delta_history.h"
24 #include "cc/metrics/dropped_frame_counter.h"
25 #include "cc/metrics/event_latency_tracing_recorder.h"
26 #include "cc/metrics/event_latency_tracker.h"
27 #include "cc/metrics/frame_sequence_tracker.h"
28 #include "cc/metrics/latency_ukm_reporter.h"
29 #include "services/tracing/public/cpp/perfetto/macros.h"
30 #include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_frame_reporter.pbzero.h"
31 #include "ui/events/types/event_type.h"
36 using StageType = CompositorFrameReporter::StageType;
37 using FrameReportType = CompositorFrameReporter::FrameReportType;
38 using BlinkBreakdown = CompositorFrameReporter::BlinkBreakdown;
39 using VizBreakdown = CompositorFrameReporter::VizBreakdown;
40 using FrameFinalState = FrameInfo::FrameFinalState;
42 constexpr int kFrameReportTypeCount =
43 static_cast<int>(FrameReportType::kMaxValue) + 1;
44 constexpr int kStageTypeCount = static_cast<int>(StageType::kStageTypeCount);
45 constexpr int kAllBreakdownCount =
46 static_cast<int>(VizBreakdown::kBreakdownCount) +
47 static_cast<int>(BlinkBreakdown::kBreakdownCount);
49 constexpr int kVizBreakdownInitialIndex = kStageTypeCount;
50 constexpr int kBlinkBreakdownInitialIndex =
51 kVizBreakdownInitialIndex + static_cast<int>(VizBreakdown::kBreakdownCount);
53 // For each possible FrameSequenceTrackerType there will be a UMA histogram
54 // plus one for general case.
55 constexpr int kFrameSequenceTrackerTypeCount =
56 static_cast<int>(FrameSequenceTrackerType::kMaxType) + 1;
58 // Maximum number of partial update dependents a reporter can own. When a
59 // reporter with too many dependents is terminated, it will terminate all its
60 // dependents which will block the pipeline for a long time. Too many dependents
61 // also means too much memory usage.
62 constexpr size_t kMaxOwnedPartialUpdateDependents = 300u;
64 // Names for CompositorFrameReporter::FrameReportType, which should be
65 // updated in case of changes to the enum.
66 constexpr const char* kReportTypeNames[]{
67 "", "MissedDeadlineFrame.", "DroppedFrame.", "CompositorOnlyFrame."};
69 static_assert(std::size(kReportTypeNames) == kFrameReportTypeCount,
70 "Compositor latency report types has changed.");
72 // This value should be recalculated in case of changes to the number of values
73 // in CompositorFrameReporter::DroppedFrameReportType or in
74 // CompositorFrameReporter::StageType
75 constexpr int kStagesWithBreakdownCount = kStageTypeCount + kAllBreakdownCount;
76 constexpr int kMaxCompositorLatencyHistogramIndex =
77 kFrameReportTypeCount *
78 (kFrameSequenceTrackerTypeCount + kStagesWithBreakdownCount);
80 constexpr base::TimeDelta kCompositorLatencyHistogramMin =
81 base::Microseconds(1);
82 constexpr base::TimeDelta kCompositorLatencyHistogramMax =
83 base::Milliseconds(350);
84 constexpr int kCompositorLatencyHistogramBucketCount = 50;
86 constexpr const char kEventLatencyBaseHistogramName[] = "EventLatency";
87 constexpr int kEventLatencyEventTypeCount =
88 static_cast<int>(EventMetrics::EventType::kMaxValue) + 1;
90 // Scroll and pinch events report a separate metrics for each input type. Scroll
91 // events also report an aggregate metric over all input types. Other event
92 // types just report one aggregate metric. So, maximum possible metrics for an
93 // event type is `max(scroll-types-count, pinch-types-count) + 1`.
94 constexpr int kEventLatencyScrollTypeCount =
95 static_cast<int>(ScrollEventMetrics::ScrollType::kMaxValue) + 1;
96 constexpr int kEventLatencyPinchTypeCount =
97 static_cast<int>(PinchEventMetrics::PinchType::kMaxValue) + 1;
98 constexpr int kEventLatencyGestureTypeCount =
99 std::max(kEventLatencyScrollTypeCount, kEventLatencyPinchTypeCount) + 1;
101 constexpr int kMaxEventLatencyHistogramIndex =
102 kEventLatencyEventTypeCount * kEventLatencyGestureTypeCount;
103 constexpr base::TimeDelta kEventLatencyHistogramMin = base::Microseconds(1);
104 constexpr base::TimeDelta kEventLatencyHistogramMax = base::Seconds(5);
105 constexpr int kEventLatencyHistogramBucketCount = 100;
106 constexpr base::TimeDelta kHighLatencyMin = base::Milliseconds(75);
108 // Number of breakdown stages of the current PipelineReporter
109 constexpr int kNumOfCompositorStages =
110 static_cast<int>(StageType::kStageTypeCount) - 1;
111 // Number of breakdown stages of the blink
112 constexpr int kNumOfBlinkStages =
113 static_cast<int>(BlinkBreakdown::kBreakdownCount);
114 // Number of breakdown stages of the viz
115 constexpr int kNumOfVizStages = static_cast<int>(VizBreakdown::kBreakdownCount);
116 // Number of dispatch stages of the current EventLatency
117 constexpr int kNumDispatchStages =
118 static_cast<int>(EventMetrics::DispatchStage::kMaxValue);
119 // Stores the weight of the most recent data point used in percentage when
120 // predicting substages' latency. (It is stored and calculated in percentage
121 // since TimeDelta calculate based on microseconds instead of nanoseconds,
122 // therefore, decimals of stage durations in microseconds may be lost.)
123 constexpr double kWeightOfCurStageInPercent = 25;
124 // Used for comparing doubles
125 constexpr double kEpsilon = 0.001;
127 std::string GetCompositorLatencyHistogramName(
128 FrameReportType report_type,
129 FrameSequenceTrackerType frame_sequence_tracker_type,
130 StageType stage_type,
131 absl::optional<VizBreakdown> viz_breakdown,
132 absl::optional<BlinkBreakdown> blink_breakdown) {
133 DCHECK_LE(frame_sequence_tracker_type, FrameSequenceTrackerType::kMaxType);
134 const char* tracker_type_name =
135 FrameSequenceTracker::GetFrameSequenceTrackerTypeName(
136 frame_sequence_tracker_type);
137 DCHECK(tracker_type_name);
138 bool impl_only_frame = report_type == FrameReportType::kCompositorOnlyFrame;
140 {"CompositorLatency.", kReportTypeNames[static_cast<int>(report_type)],
141 tracker_type_name, *tracker_type_name ? "." : "",
142 CompositorFrameReporter::GetStageName(
143 stage_type, viz_breakdown, blink_breakdown, impl_only_frame)});
146 // Helper function to record UMA histogram for an EventLatency metric. There
147 // should be a 1:1 mapping between `name` and `index` to allow the use of
148 // `STATIC_HISTOGRAM_POINTER_GROUP()` to cache histogram objects.
149 void ReportEventLatencyMetric(const std::string& name,
151 base::TimeDelta latency) {
152 STATIC_HISTOGRAM_POINTER_GROUP(
153 name, index, kMaxEventLatencyHistogramIndex,
154 AddTimeMicrosecondsGranularity(latency),
155 base::Histogram::FactoryMicrosecondsTimeGet(
156 name, kEventLatencyHistogramMin, kEventLatencyHistogramMax,
157 kEventLatencyHistogramBucketCount,
158 base::HistogramBase::kUmaTargetedHistogramFlag));
161 constexpr char kTraceCategory[] =
162 "cc,benchmark," TRACE_DISABLED_BY_DEFAULT("devtools.timeline.frame");
164 base::TimeTicks ComputeSafeDeadlineForFrame(const viz::BeginFrameArgs& args) {
165 return args.frame_time + (args.interval * 1.5);
168 // Returns the value of the exponentially weighted average for
169 // SetEventLatencyPredictions.
170 base::TimeDelta CalculateWeightedAverage(base::TimeDelta previous_value,
171 base::TimeDelta current_value) {
172 if (previous_value.is_negative())
173 return current_value;
174 return (kWeightOfCurStageInPercent * current_value +
175 (100 - kWeightOfCurStageInPercent) * previous_value) /
179 // Calculate new prediction of latency based on old prediction and current
181 base::TimeDelta PredictLatency(base::TimeDelta previous_prediction,
182 base::TimeDelta current_latency) {
183 return (kWeightOfCurStageInPercent * current_latency +
184 (100 - kWeightOfCurStageInPercent) * previous_prediction) /
188 double DetermineHighestContribution(
189 double contribution_change,
190 double highest_contribution_change,
191 const std::string& stage_name,
192 std::vector<std::string>& high_latency_stages) {
193 if (std::abs(contribution_change - highest_contribution_change) < kEpsilon) {
194 high_latency_stages.push_back(stage_name);
195 } else if (contribution_change > highest_contribution_change) {
196 highest_contribution_change = contribution_change;
197 high_latency_stages = {stage_name};
199 return highest_contribution_change;
204 // CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator ==================
206 CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::Iterator(
207 const ProcessedBlinkBreakdown* owner)
210 CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::~Iterator() =
213 bool CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::IsValid()
215 return index_ < std::size(owner_->list_);
218 void CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::Advance() {
224 CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::GetBreakdown()
227 return static_cast<BlinkBreakdown>(index_);
231 CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator::GetLatency() const {
233 return owner_->list_[index_];
236 // CompositorFrameReporter::ProcessedBlinkBreakdown ============================
238 CompositorFrameReporter::ProcessedBlinkBreakdown::ProcessedBlinkBreakdown(
239 base::TimeTicks blink_start_time,
240 base::TimeTicks begin_main_frame_start,
241 const BeginMainFrameMetrics& blink_breakdown) {
242 if (blink_start_time.is_null())
245 list_[static_cast<int>(BlinkBreakdown::kHandleInputEvents)] =
246 blink_breakdown.handle_input_events;
247 list_[static_cast<int>(BlinkBreakdown::kAnimate)] = blink_breakdown.animate;
248 list_[static_cast<int>(BlinkBreakdown::kStyleUpdate)] =
249 blink_breakdown.style_update;
250 list_[static_cast<int>(BlinkBreakdown::kLayoutUpdate)] =
251 blink_breakdown.layout_update;
252 list_[static_cast<int>(BlinkBreakdown::kAccessibility)] =
253 blink_breakdown.accessibility;
254 list_[static_cast<int>(BlinkBreakdown::kPrepaint)] = blink_breakdown.prepaint;
255 list_[static_cast<int>(BlinkBreakdown::kCompositingInputs)] =
256 blink_breakdown.compositing_inputs;
257 list_[static_cast<int>(BlinkBreakdown::kPaint)] = blink_breakdown.paint;
258 list_[static_cast<int>(BlinkBreakdown::kCompositeCommit)] =
259 blink_breakdown.composite_commit;
260 list_[static_cast<int>(BlinkBreakdown::kUpdateLayers)] =
261 blink_breakdown.update_layers;
262 list_[static_cast<int>(BlinkBreakdown::kBeginMainSentToStarted)] =
263 begin_main_frame_start - blink_start_time;
266 CompositorFrameReporter::ProcessedBlinkBreakdown::~ProcessedBlinkBreakdown() =
269 CompositorFrameReporter::ProcessedBlinkBreakdown::Iterator
270 CompositorFrameReporter::ProcessedBlinkBreakdown::CreateIterator() const {
271 return Iterator(this);
274 // CompositorFrameReporter::ProcessedVizBreakdown::Iterator ====================
276 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::Iterator(
277 const ProcessedVizBreakdown* owner,
278 bool skip_swap_start_to_swap_end)
279 : owner_(owner), skip_swap_start_to_swap_end_(skip_swap_start_to_swap_end) {
283 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::~Iterator() = default;
285 bool CompositorFrameReporter::ProcessedVizBreakdown::Iterator::IsValid() const {
286 return index_ < std::size(owner_->list_) && owner_->list_[index_];
289 void CompositorFrameReporter::ProcessedVizBreakdown::Iterator::Advance() {
292 if (static_cast<VizBreakdown>(index_) == VizBreakdown::kSwapStartToSwapEnd &&
293 skip_swap_start_to_swap_end_) {
299 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::GetBreakdown() const {
301 return static_cast<VizBreakdown>(index_);
305 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::GetStartTime() const {
307 return owner_->list_[index_]->first;
311 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::GetEndTime() const {
313 return owner_->list_[index_]->second;
317 CompositorFrameReporter::ProcessedVizBreakdown::Iterator::GetDuration() const {
319 return owner_->list_[index_]->second - owner_->list_[index_]->first;
322 // CompositorFrameReporter::ProcessedVizBreakdown ==============================
324 CompositorFrameReporter::ProcessedVizBreakdown::ProcessedVizBreakdown(
325 base::TimeTicks viz_start_time,
326 const viz::FrameTimingDetails& viz_breakdown) {
327 if (viz_start_time.is_null())
330 // Check if `viz_breakdown` is set. Testing indicates that sometimes the
331 // received_compositor_frame_timestamp can be earlier than the given
332 // `viz_start_time`. Avoid reporting negative times.
333 if (viz_breakdown.received_compositor_frame_timestamp.is_null() ||
334 viz_breakdown.received_compositor_frame_timestamp < viz_start_time) {
337 list_[static_cast<int>(VizBreakdown::kSubmitToReceiveCompositorFrame)] =
338 std::make_pair(viz_start_time,
339 viz_breakdown.received_compositor_frame_timestamp);
341 if (viz_breakdown.draw_start_timestamp.is_null())
343 list_[static_cast<int>(VizBreakdown::kReceivedCompositorFrameToStartDraw)] =
344 std::make_pair(viz_breakdown.received_compositor_frame_timestamp,
345 viz_breakdown.draw_start_timestamp);
347 if (viz_breakdown.swap_timings.is_null())
349 list_[static_cast<int>(VizBreakdown::kStartDrawToSwapStart)] =
350 std::make_pair(viz_breakdown.draw_start_timestamp,
351 viz_breakdown.swap_timings.swap_start);
353 list_[static_cast<int>(VizBreakdown::kSwapStartToSwapEnd)] =
354 std::make_pair(viz_breakdown.swap_timings.swap_start,
355 viz_breakdown.swap_timings.swap_end);
357 list_[static_cast<int>(VizBreakdown::kSwapEndToPresentationCompositorFrame)] =
358 std::make_pair(viz_breakdown.swap_timings.swap_end,
359 viz_breakdown.presentation_feedback.timestamp);
360 swap_start_ = viz_breakdown.swap_timings.swap_start;
362 if (viz_breakdown.presentation_feedback.ready_timestamp.is_null())
364 buffer_ready_available_ = true;
365 list_[static_cast<int>(VizBreakdown::kSwapStartToBufferAvailable)] =
366 std::make_pair(viz_breakdown.swap_timings.swap_start,
367 viz_breakdown.presentation_feedback.available_timestamp);
368 list_[static_cast<int>(VizBreakdown::kBufferAvailableToBufferReady)] =
369 std::make_pair(viz_breakdown.presentation_feedback.available_timestamp,
370 viz_breakdown.presentation_feedback.ready_timestamp);
371 list_[static_cast<int>(VizBreakdown::kBufferReadyToLatch)] =
372 std::make_pair(viz_breakdown.presentation_feedback.ready_timestamp,
373 viz_breakdown.presentation_feedback.latch_timestamp);
374 list_[static_cast<int>(VizBreakdown::kLatchToSwapEnd)] =
375 std::make_pair(viz_breakdown.presentation_feedback.latch_timestamp,
376 viz_breakdown.swap_timings.swap_end);
379 CompositorFrameReporter::ProcessedVizBreakdown::~ProcessedVizBreakdown() =
382 CompositorFrameReporter::ProcessedVizBreakdown::Iterator
383 CompositorFrameReporter::ProcessedVizBreakdown::CreateIterator(
384 bool skip_swap_start_to_swap_end_if_breakdown_available) const {
385 return Iterator(this, skip_swap_start_to_swap_end_if_breakdown_available &&
386 buffer_ready_available_);
389 // CompositorFrameReporter::CompositorLatencyInfo ==============================
391 CompositorFrameReporter::CompositorLatencyInfo::CompositorLatencyInfo() =
393 CompositorFrameReporter::CompositorLatencyInfo::CompositorLatencyInfo(
394 base::TimeDelta init_value)
395 : top_level_stages(kNumOfCompositorStages, init_value),
396 blink_breakdown_stages(kNumOfBlinkStages, init_value),
397 viz_breakdown_stages(kNumOfVizStages, init_value),
398 total_latency(init_value),
399 total_blink_latency(init_value),
400 total_viz_latency(init_value) {}
401 CompositorFrameReporter::CompositorLatencyInfo::~CompositorLatencyInfo() =
404 // CompositorFrameReporter =====================================================
406 CompositorFrameReporter::CompositorFrameReporter(
407 const ActiveTrackers& active_trackers,
408 const viz::BeginFrameArgs& args,
409 bool should_report_histograms,
410 SmoothThread smooth_thread,
411 FrameInfo::SmoothEffectDrivingThread scrolling_thread,
412 int layer_tree_host_id,
413 const GlobalMetricsTrackers& trackers)
414 : should_report_histograms_(should_report_histograms),
416 active_trackers_(active_trackers),
417 scrolling_thread_(scrolling_thread),
418 smooth_thread_(smooth_thread),
419 layer_tree_host_id_(layer_tree_host_id),
420 global_trackers_(trackers) {
421 DCHECK(global_trackers_.dropped_frame_counter);
422 global_trackers_.dropped_frame_counter->OnBeginFrame(
423 args, IsScrollActive(active_trackers_));
424 DCHECK(IsScrollActive(active_trackers_) ||
425 scrolling_thread_ == FrameInfo::SmoothEffectDrivingThread::kUnknown);
426 if (scrolling_thread_ == FrameInfo::SmoothEffectDrivingThread::kCompositor) {
427 DCHECK(smooth_thread_ == SmoothThread::kSmoothCompositor ||
428 smooth_thread_ == SmoothThread::kSmoothBoth);
429 } else if (scrolling_thread_ == FrameInfo::SmoothEffectDrivingThread::kMain) {
430 DCHECK(smooth_thread_ == SmoothThread::kSmoothMain ||
431 smooth_thread_ == SmoothThread::kSmoothBoth);
433 // If we have a SET version of the animation, then we should also have a
434 // non-SET version of the same animation.
435 DCHECK(!active_trackers_.test(static_cast<size_t>(
436 FrameSequenceTrackerType::kSETCompositorAnimation)) ||
437 active_trackers_.test(static_cast<size_t>(
438 FrameSequenceTrackerType::kCompositorAnimation)));
439 DCHECK(!active_trackers_.test(static_cast<size_t>(
440 FrameSequenceTrackerType::kSETMainThreadAnimation)) ||
441 active_trackers_.test(static_cast<size_t>(
442 FrameSequenceTrackerType::kMainThreadAnimation)));
444 is_backfill_ = false;
448 const char* CompositorFrameReporter::GetStageName(
449 StageType stage_type,
450 absl::optional<VizBreakdown> viz_breakdown,
451 absl::optional<BlinkBreakdown> blink_breakdown,
453 DCHECK(!viz_breakdown ||
455 StageType::kSubmitCompositorFrameToPresentationCompositorFrame);
456 DCHECK(!blink_breakdown ||
457 stage_type == StageType::kSendBeginMainFrameToCommit);
458 switch (stage_type) {
459 case StageType::kBeginImplFrameToSendBeginMainFrame:
460 return impl_only ? "BeginImplFrameToFinishImpl"
461 : "BeginImplFrameToSendBeginMainFrame";
462 case StageType::kSendBeginMainFrameToCommit:
463 if (!blink_breakdown) {
464 return impl_only ? "SendBeginMainFrameToBeginMainAbort"
465 : "SendBeginMainFrameToCommit";
467 switch (*blink_breakdown) {
468 case BlinkBreakdown::kHandleInputEvents:
469 return "SendBeginMainFrameToCommit.HandleInputEvents";
470 case BlinkBreakdown::kAnimate:
471 return "SendBeginMainFrameToCommit.Animate";
472 case BlinkBreakdown::kStyleUpdate:
473 return "SendBeginMainFrameToCommit.StyleUpdate";
474 case BlinkBreakdown::kLayoutUpdate:
475 return "SendBeginMainFrameToCommit.LayoutUpdate";
476 case BlinkBreakdown::kAccessibility:
477 return "SendBeginMainFrameToCommit.AccessibiltyUpdate";
478 case BlinkBreakdown::kPrepaint:
479 return "SendBeginMainFrameToCommit.Prepaint";
480 case BlinkBreakdown::kCompositingInputs:
481 return "SendBeginMainFrameToCommit.CompositingInputs";
482 case BlinkBreakdown::kPaint:
483 return "SendBeginMainFrameToCommit.Paint";
484 case BlinkBreakdown::kCompositeCommit:
485 return "SendBeginMainFrameToCommit.CompositeCommit";
486 case BlinkBreakdown::kUpdateLayers:
487 return "SendBeginMainFrameToCommit.UpdateLayers";
488 case BlinkBreakdown::kBeginMainSentToStarted:
489 return "SendBeginMainFrameToCommit.BeginMainSentToStarted";
490 case BlinkBreakdown::kBreakdownCount:
494 case StageType::kCommit:
496 case StageType::kEndCommitToActivation:
497 return "EndCommitToActivation";
498 case StageType::kActivation:
500 case StageType::kEndActivateToSubmitCompositorFrame:
501 return impl_only ? "ImplFrameDoneToSubmitCompositorFrame"
502 : "EndActivateToSubmitCompositorFrame";
503 case StageType::kSubmitCompositorFrameToPresentationCompositorFrame:
505 return "SubmitCompositorFrameToPresentationCompositorFrame";
506 switch (*viz_breakdown) {
507 case VizBreakdown::kSubmitToReceiveCompositorFrame:
508 return "SubmitCompositorFrameToPresentationCompositorFrame."
509 "SubmitToReceiveCompositorFrame";
510 case VizBreakdown::kReceivedCompositorFrameToStartDraw:
511 return "SubmitCompositorFrameToPresentationCompositorFrame."
512 "ReceivedCompositorFrameToStartDraw";
513 case VizBreakdown::kStartDrawToSwapStart:
514 return "SubmitCompositorFrameToPresentationCompositorFrame."
515 "StartDrawToSwapStart";
516 case VizBreakdown::kSwapStartToSwapEnd:
517 return "SubmitCompositorFrameToPresentationCompositorFrame."
518 "SwapStartToSwapEnd";
519 case VizBreakdown::kSwapEndToPresentationCompositorFrame:
520 return "SubmitCompositorFrameToPresentationCompositorFrame."
521 "SwapEndToPresentationCompositorFrame";
522 case VizBreakdown::kSwapStartToBufferAvailable:
523 return "SubmitCompositorFrameToPresentationCompositorFrame."
524 "SwapStartToBufferAvailable";
525 case VizBreakdown::kBufferAvailableToBufferReady:
526 return "SubmitCompositorFrameToPresentationCompositorFrame."
527 "BufferAvailableToBufferReady";
528 case VizBreakdown::kBufferReadyToLatch:
529 return "SubmitCompositorFrameToPresentationCompositorFrame."
530 "BufferReadyToLatch";
531 case VizBreakdown::kLatchToSwapEnd:
532 return "SubmitCompositorFrameToPresentationCompositorFrame."
534 case VizBreakdown::kBreakdownCount:
538 case StageType::kTotalLatency:
539 return "TotalLatency";
540 case StageType::kStageTypeCount:
547 const char* CompositorFrameReporter::GetVizBreakdownName(
548 VizBreakdown breakdown) {
550 case VizBreakdown::kSubmitToReceiveCompositorFrame:
551 return "SubmitToReceiveCompositorFrame";
552 case VizBreakdown::kReceivedCompositorFrameToStartDraw:
553 return "ReceiveCompositorFrameToStartDraw";
554 case VizBreakdown::kStartDrawToSwapStart:
555 return "StartDrawToSwapStart";
556 case VizBreakdown::kSwapStartToSwapEnd:
558 case VizBreakdown::kSwapEndToPresentationCompositorFrame:
559 return "SwapEndToPresentationCompositorFrame";
560 case VizBreakdown::kSwapStartToBufferAvailable:
561 return "SwapStartToBufferAvailable";
562 case VizBreakdown::kBufferAvailableToBufferReady:
563 return "BufferAvailableToBufferReady";
564 case VizBreakdown::kBufferReadyToLatch:
565 return "BufferReadyToLatch";
566 case VizBreakdown::kLatchToSwapEnd:
567 return "LatchToSwapEnd";
568 case VizBreakdown::kBreakdownCount:
574 std::unique_ptr<CompositorFrameReporter>
575 CompositorFrameReporter::CopyReporterAtBeginImplStage() {
576 // If |this| reporter is dependent on another reporter to decide about partial
577 // update, then |this| should not have any such dependents.
578 DCHECK(!partial_update_decider_);
580 if (stage_history_.empty() ||
581 stage_history_.front().stage_type !=
582 StageType::kBeginImplFrameToSendBeginMainFrame ||
583 (!did_finish_impl_frame() && !did_not_produce_frame_time_.has_value())) {
586 auto new_reporter = std::make_unique<CompositorFrameReporter>(
587 active_trackers_, args_, should_report_histograms_, smooth_thread_,
588 scrolling_thread_, layer_tree_host_id_, global_trackers_);
589 new_reporter->did_finish_impl_frame_ = did_finish_impl_frame_;
590 new_reporter->impl_frame_finish_time_ = impl_frame_finish_time_;
591 new_reporter->main_frame_abort_time_ = main_frame_abort_time_;
592 new_reporter->current_stage_.stage_type =
593 StageType::kBeginImplFrameToSendBeginMainFrame;
594 new_reporter->current_stage_.start_time = stage_history_.front().start_time;
595 new_reporter->set_tick_clock(tick_clock_);
596 new_reporter->set_is_forked(true);
598 // Set up the new reporter so that it depends on |this| for partial update
600 new_reporter->SetPartialUpdateDecider(this);
605 CompositorFrameReporter::~CompositorFrameReporter() {
609 CompositorFrameReporter::StageData::StageData() = default;
610 CompositorFrameReporter::StageData::StageData(StageType stage_type,
611 base::TimeTicks start_time,
612 base::TimeTicks end_time)
613 : stage_type(stage_type), start_time(start_time), end_time(end_time) {}
614 CompositorFrameReporter::StageData::StageData(const StageData&) = default;
615 CompositorFrameReporter::StageData::~StageData() = default;
617 CompositorFrameReporter::EventLatencyInfo::EventLatencyInfo(
618 const int num_dispatch_stages,
619 const int num_compositor_stages)
620 : dispatch_durations(num_dispatch_stages, base::Microseconds(-1)),
621 transition_duration(base::Microseconds(-1)),
622 compositor_durations(num_compositor_stages, base::Microseconds(-1)),
623 total_duration(base::Microseconds(-1)),
624 transition_name("") {}
625 CompositorFrameReporter::EventLatencyInfo::~EventLatencyInfo() = default;
627 void CompositorFrameReporter::StartStage(
628 CompositorFrameReporter::StageType stage_type,
629 base::TimeTicks start_time) {
630 if (frame_termination_status_ != FrameTerminationStatus::kUnknown)
632 EndCurrentStage(start_time);
633 current_stage_.stage_type = stage_type;
634 current_stage_.start_time = start_time;
635 switch (stage_type) {
636 case StageType::kSendBeginMainFrameToCommit:
637 DCHECK(blink_start_time_.is_null());
638 blink_start_time_ = start_time;
640 case StageType::kSubmitCompositorFrameToPresentationCompositorFrame:
641 DCHECK(viz_start_time_.is_null());
642 viz_start_time_ = start_time;
649 void CompositorFrameReporter::TerminateFrame(
650 FrameTerminationStatus termination_status,
651 base::TimeTicks termination_time) {
652 // If the reporter is already terminated, (possibly as a result of no damage)
653 // then we don't need to do anything here, otherwise the reporter will be
655 if (frame_termination_status_ != FrameTerminationStatus::kUnknown)
657 frame_termination_status_ = termination_status;
658 frame_termination_time_ = termination_time;
659 EndCurrentStage(frame_termination_time_);
662 void CompositorFrameReporter::OnFinishImplFrame(base::TimeTicks timestamp) {
663 DCHECK(!did_finish_impl_frame_);
665 did_finish_impl_frame_ = true;
666 impl_frame_finish_time_ = timestamp;
669 void CompositorFrameReporter::OnAbortBeginMainFrame(base::TimeTicks timestamp) {
670 DCHECK(!main_frame_abort_time_.has_value());
671 main_frame_abort_time_ = timestamp;
672 impl_frame_finish_time_ = timestamp;
673 // impl_frame_finish_time_ can be used for the end of BeginMain to Commit
677 void CompositorFrameReporter::OnDidNotProduceFrame(
678 FrameSkippedReason skip_reason) {
679 did_not_produce_frame_time_ = Now();
680 frame_skip_reason_ = skip_reason;
683 void CompositorFrameReporter::EnableCompositorOnlyReporting() {
684 EnableReportType(FrameReportType::kCompositorOnlyFrame);
687 void CompositorFrameReporter::SetBlinkBreakdown(
688 std::unique_ptr<BeginMainFrameMetrics> blink_breakdown,
689 base::TimeTicks begin_main_start) {
690 DCHECK(blink_breakdown_.paint.is_zero());
692 blink_breakdown_ = *blink_breakdown;
694 blink_breakdown_ = BeginMainFrameMetrics();
696 DCHECK(begin_main_frame_start_.is_null());
697 begin_main_frame_start_ = begin_main_start;
700 void CompositorFrameReporter::SetVizBreakdown(
701 const viz::FrameTimingDetails& viz_breakdown) {
702 DCHECK(viz_breakdown_.received_compositor_frame_timestamp.is_null());
703 viz_breakdown_ = viz_breakdown;
706 void CompositorFrameReporter::AddEventsMetrics(
707 EventMetrics::List events_metrics) {
708 events_metrics_.insert(events_metrics_.end(),
709 std::make_move_iterator(events_metrics.begin()),
710 std::make_move_iterator(events_metrics.end()));
713 EventMetrics::List CompositorFrameReporter::TakeEventsMetrics() {
714 EventMetrics::List result = std::move(events_metrics_);
715 events_metrics_.clear();
719 EventMetrics::List CompositorFrameReporter::TakeMainBlockedEventsMetrics() {
720 auto mid = std::partition(events_metrics_.begin(), events_metrics_.end(),
721 [](std::unique_ptr<EventMetrics>& metrics) {
723 bool is_blocked_on_main =
724 metrics->requires_main_thread_update();
725 // Invert so we can take from the end.
726 return !is_blocked_on_main;
728 EventMetrics::List result(std::make_move_iterator(mid),
729 std::make_move_iterator(events_metrics_.end()));
730 events_metrics_.erase(mid, events_metrics_.end());
734 void CompositorFrameReporter::TerminateReporter() {
735 if (frame_termination_status_ == FrameTerminationStatus::kUnknown)
736 TerminateFrame(FrameTerminationStatus::kUnknown, Now());
738 if (!processed_blink_breakdown_)
739 processed_blink_breakdown_ = std::make_unique<ProcessedBlinkBreakdown>(
740 blink_start_time_, begin_main_frame_start_, blink_breakdown_);
741 if (!processed_viz_breakdown_)
742 processed_viz_breakdown_ = std::make_unique<ProcessedVizBreakdown>(
743 viz_start_time_, viz_breakdown_);
745 DCHECK_EQ(current_stage_.start_time, base::TimeTicks());
746 const FrameInfo frame_info = GenerateFrameInfo();
747 switch (frame_info.final_state) {
748 case FrameFinalState::kDropped:
749 EnableReportType(FrameReportType::kDroppedFrame);
752 case FrameFinalState::kNoUpdateDesired:
753 // If this reporter was cloned, and the cloned reporter was marked as
754 // containing 'partial update' (i.e. missing desired updates from the
755 // main-thread), but this reporter terminated with 'no damage', then reset
756 // the 'partial update' flag from the cloned reporter (as well as other
757 // depending reporters).
758 while (!partial_update_dependents_.empty()) {
759 auto dependent = partial_update_dependents_.front();
761 dependent->set_has_partial_update(false);
762 partial_update_dependents_.pop();
766 case FrameFinalState::kPresentedAll:
767 case FrameFinalState::kPresentedPartialNewMain:
768 case FrameFinalState::kPresentedPartialOldMain:
769 EnableReportType(FrameReportType::kNonDroppedFrame);
770 if (ComputeSafeDeadlineForFrame(args_) < frame_termination_time_)
771 EnableReportType(FrameReportType::kMissedDeadlineFrame);
775 ReportCompositorLatencyTraceEvents(frame_info);
776 if (TestReportType(FrameReportType::kNonDroppedFrame))
777 ReportEventLatencyTraceEvents();
779 // Only report compositor latency metrics if the frame was produced.
780 if (report_types_.any() &&
781 (should_report_histograms_ || global_trackers_.latency_ukm_reporter ||
782 global_trackers_.event_latency_tracker)) {
783 DCHECK(stage_history_.size());
784 DCHECK_EQ(SumOfStageHistory(), stage_history_.back().end_time -
785 stage_history_.front().start_time);
786 stage_history_.emplace_back(StageType::kTotalLatency,
787 stage_history_.front().start_time,
788 stage_history_.back().end_time);
790 ReportCompositorLatencyMetrics();
792 // Only report event latency metrics if the frame was presented.
793 if (TestReportType(FrameReportType::kNonDroppedFrame))
794 ReportEventLatencyMetrics();
797 if (TestReportType(FrameReportType::kDroppedFrame)) {
798 global_trackers_.dropped_frame_counter->AddDroppedFrame();
800 if (has_partial_update_)
801 global_trackers_.dropped_frame_counter->AddPartialFrame();
803 global_trackers_.dropped_frame_counter->AddGoodFrame();
805 global_trackers_.dropped_frame_counter->OnEndFrame(args_, frame_info);
807 if (discarded_partial_update_dependents_count_ > 0)
808 UMA_HISTOGRAM_CUSTOM_COUNTS(
809 "Graphics.Smoothness.Diagnostic.DiscardedDependentCount",
810 discarded_partial_update_dependents_count_, 1, 1000, 50);
813 void CompositorFrameReporter::EndCurrentStage(base::TimeTicks end_time) {
814 if (current_stage_.start_time == base::TimeTicks())
816 current_stage_.end_time = end_time;
817 stage_history_.push_back(current_stage_);
818 current_stage_.start_time = base::TimeTicks();
821 void CompositorFrameReporter::ReportCompositorLatencyMetrics() const {
822 if (!base::ShouldLogHistogramForCpuReductionExperiment())
825 if (global_trackers_.latency_ukm_reporter) {
826 global_trackers_.latency_ukm_reporter->ReportCompositorLatencyUkm(
827 report_types_, stage_history_, active_trackers_,
828 *processed_blink_breakdown_, *processed_viz_breakdown_);
831 if (!should_report_histograms_)
834 for (const StageData& stage : stage_history_) {
835 ReportStageHistogramWithBreakdown(stage);
837 if (stage.stage_type == StageType::kTotalLatency) {
838 for (size_t type = 0; type < active_trackers_.size(); ++type) {
839 if (active_trackers_.test(type)) {
840 // Report stage breakdowns.
841 ReportStageHistogramWithBreakdown(
842 stage, static_cast<FrameSequenceTrackerType>(type));
848 for (size_t type = 0; type < report_types_.size(); ++type) {
849 if (!report_types_.test(type))
851 FrameReportType report_type = static_cast<FrameReportType>(type);
852 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type", report_type);
853 bool any_active_interaction = false;
854 for (size_t fst_type = 0; fst_type < active_trackers_.size(); ++fst_type) {
855 const auto tracker_type = static_cast<FrameSequenceTrackerType>(fst_type);
856 if (!active_trackers_.test(fst_type) ||
857 tracker_type == FrameSequenceTrackerType::kCustom ||
858 tracker_type == FrameSequenceTrackerType::kMaxType) {
861 any_active_interaction = true;
862 switch (tracker_type) {
863 case FrameSequenceTrackerType::kCompositorAnimation:
864 UMA_HISTOGRAM_ENUMERATION(
865 "CompositorLatency.Type.CompositorAnimation", report_type);
867 case FrameSequenceTrackerType::kMainThreadAnimation:
868 UMA_HISTOGRAM_ENUMERATION(
869 "CompositorLatency.Type.MainThreadAnimation", report_type);
871 case FrameSequenceTrackerType::kPinchZoom:
872 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.PinchZoom",
875 case FrameSequenceTrackerType::kRAF:
876 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.RAF", report_type);
878 case FrameSequenceTrackerType::kTouchScroll:
879 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.TouchScroll",
882 case FrameSequenceTrackerType::kVideo:
883 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.Video",
886 case FrameSequenceTrackerType::kWheelScroll:
887 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.WheelScroll",
890 case FrameSequenceTrackerType::kScrollbarScroll:
891 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.ScrollbarScroll",
894 case FrameSequenceTrackerType::kCanvasAnimation:
895 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.CanvasAnimation",
898 case FrameSequenceTrackerType::kJSAnimation:
899 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.JSAnimation",
902 case FrameSequenceTrackerType::kSETCompositorAnimation:
903 UMA_HISTOGRAM_ENUMERATION(
904 "CompositorLatency.Type.SETCompositorAnimation", report_type);
906 case FrameSequenceTrackerType::kSETMainThreadAnimation:
907 UMA_HISTOGRAM_ENUMERATION(
908 "CompositorLatency.Type.SETMainThreadAnimation", report_type);
910 case FrameSequenceTrackerType::kCustom:
911 case FrameSequenceTrackerType::kMaxType:
916 if (any_active_interaction) {
917 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.AnyInteraction",
920 UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type.NoInteraction",
926 void CompositorFrameReporter::ReportStageHistogramWithBreakdown(
927 const CompositorFrameReporter::StageData& stage,
928 FrameSequenceTrackerType frame_sequence_tracker_type) const {
929 base::TimeDelta stage_delta = stage.end_time - stage.start_time;
930 ReportCompositorLatencyHistogram(
931 frame_sequence_tracker_type, stage.stage_type,
932 /*viz_breakdown=*/absl::nullopt,
933 /*blink_breakdown=*/absl::nullopt, stage_delta);
934 switch (stage.stage_type) {
935 case StageType::kSendBeginMainFrameToCommit:
936 ReportCompositorLatencyBlinkBreakdowns(frame_sequence_tracker_type);
938 case StageType::kSubmitCompositorFrameToPresentationCompositorFrame:
939 ReportCompositorLatencyVizBreakdowns(frame_sequence_tracker_type);
946 void CompositorFrameReporter::ReportCompositorLatencyBlinkBreakdowns(
947 FrameSequenceTrackerType frame_sequence_tracker_type) const {
948 DCHECK(processed_blink_breakdown_);
949 for (auto it = processed_blink_breakdown_->CreateIterator(); it.IsValid();
951 ReportCompositorLatencyHistogram(
952 frame_sequence_tracker_type, StageType::kSendBeginMainFrameToCommit,
953 /*viz_breakdown=*/absl::nullopt, it.GetBreakdown(), it.GetLatency());
957 void CompositorFrameReporter::ReportCompositorLatencyVizBreakdowns(
958 FrameSequenceTrackerType frame_sequence_tracker_type) const {
959 DCHECK(processed_viz_breakdown_);
960 for (auto it = processed_viz_breakdown_->CreateIterator(false); it.IsValid();
962 ReportCompositorLatencyHistogram(
963 frame_sequence_tracker_type,
964 StageType::kSubmitCompositorFrameToPresentationCompositorFrame,
965 it.GetBreakdown(), /*blink_breakdown=*/absl::nullopt, it.GetDuration());
969 void CompositorFrameReporter::ReportCompositorLatencyHistogram(
970 FrameSequenceTrackerType frame_sequence_tracker_type,
971 StageType stage_type,
972 absl::optional<VizBreakdown> viz_breakdown,
973 absl::optional<BlinkBreakdown> blink_breakdown,
974 base::TimeDelta time_delta) const {
975 DCHECK(!viz_breakdown ||
977 StageType::kSubmitCompositorFrameToPresentationCompositorFrame);
978 DCHECK(!blink_breakdown ||
979 stage_type == StageType::kSendBeginMainFrameToCommit);
980 for (size_t type = 0; type < report_types_.size(); ++type) {
981 if (!report_types_.test(type))
983 FrameReportType report_type = static_cast<FrameReportType>(type);
984 const int report_type_index = static_cast<int>(report_type);
985 const int frame_sequence_tracker_type_index =
986 static_cast<int>(frame_sequence_tracker_type);
987 const int stage_type_index =
989 ? kBlinkBreakdownInitialIndex + static_cast<int>(*blink_breakdown)
991 ? kVizBreakdownInitialIndex + static_cast<int>(*viz_breakdown)
992 : static_cast<int>(stage_type);
993 const int histogram_index =
994 (stage_type_index == static_cast<int>(StageType::kTotalLatency)
995 ? kStagesWithBreakdownCount + frame_sequence_tracker_type_index
996 : stage_type_index) *
997 kFrameReportTypeCount +
1000 CHECK_LT(stage_type_index, kStagesWithBreakdownCount);
1001 CHECK_GE(stage_type_index, 0);
1002 CHECK_LT(report_type_index, kFrameReportTypeCount);
1003 CHECK_GE(report_type_index, 0);
1004 CHECK_LT(histogram_index, kMaxCompositorLatencyHistogramIndex);
1005 CHECK_GE(histogram_index, 0);
1007 // Note: There's a 1:1 mapping between `histogram_index` and the name
1008 // returned by `GetCompositorLatencyHistogramName()` which allows the use of
1009 // `STATIC_HISTOGRAM_POINTER_GROUP()` to cache histogram objects.
1010 STATIC_HISTOGRAM_POINTER_GROUP(
1011 GetCompositorLatencyHistogramName(
1012 report_type, frame_sequence_tracker_type, stage_type, viz_breakdown,
1014 histogram_index, kMaxCompositorLatencyHistogramIndex,
1015 AddTimeMicrosecondsGranularity(time_delta),
1016 base::Histogram::FactoryMicrosecondsTimeGet(
1017 GetCompositorLatencyHistogramName(
1018 report_type, frame_sequence_tracker_type, stage_type,
1019 viz_breakdown, blink_breakdown),
1020 kCompositorLatencyHistogramMin, kCompositorLatencyHistogramMax,
1021 kCompositorLatencyHistogramBucketCount,
1022 base::HistogramBase::kUmaTargetedHistogramFlag));
1026 void CompositorFrameReporter::ReportEventLatencyMetrics() const {
1027 const StageData& total_latency_stage = stage_history_.back();
1028 DCHECK_EQ(StageType::kTotalLatency, total_latency_stage.stage_type);
1030 if (global_trackers_.latency_ukm_reporter) {
1031 global_trackers_.latency_ukm_reporter->ReportEventLatencyUkm(
1032 events_metrics_, stage_history_, *processed_blink_breakdown_,
1033 *processed_viz_breakdown_);
1036 std::vector<EventLatencyTracker::LatencyData> latencies;
1038 for (const auto& event_metrics : events_metrics_) {
1039 DCHECK(event_metrics);
1040 auto* scroll_metrics = event_metrics->AsScroll();
1041 auto* pinch_metrics = event_metrics->AsPinch();
1043 const base::TimeTicks generated_timestamp =
1044 event_metrics->GetDispatchStageTimestamp(
1045 EventMetrics::DispatchStage::kGenerated);
1046 // Generally, we expect that the event timestamp is strictly smaller than
1047 // the end timestamp of the last stage (i.e. total latency is positive);
1048 // however, at least in tests, it is possible that the timestamps are the
1049 // same and total latency is zero.
1050 DCHECK_LE(generated_timestamp, total_latency_stage.end_time);
1051 const base::TimeDelta total_latency =
1052 total_latency_stage.end_time - generated_timestamp;
1054 if (should_report_histograms_) {
1055 const std::string histogram_base_name = base::JoinString(
1056 {kEventLatencyBaseHistogramName, event_metrics->GetTypeName()}, ".");
1057 const int event_histogram_index = static_cast<int>(event_metrics->type());
1058 const std::string total_latency_stage_name =
1059 GetStageName(StageType::kTotalLatency);
1061 // For pinch events, we only report metrics for each device type and not
1062 // the aggregate metric over all device types.
1063 if (!pinch_metrics) {
1064 const std::string event_total_latency_histogram_name = base::JoinString(
1065 {histogram_base_name, total_latency_stage_name}, ".");
1066 ReportEventLatencyMetric(event_total_latency_histogram_name,
1067 event_histogram_index, total_latency);
1070 // For scroll and pinch events, report metrics for each device type
1072 if (scroll_metrics || pinch_metrics) {
1073 const int gesture_type_index =
1075 ? static_cast<int>(scroll_metrics->scroll_type())
1076 : static_cast<int>(pinch_metrics->pinch_type()));
1077 const int gesture_histogram_index =
1078 event_histogram_index * kEventLatencyGestureTypeCount +
1080 const std::string gesture_type_name =
1081 scroll_metrics ? scroll_metrics->GetScrollTypeName()
1082 : pinch_metrics->GetPinchTypeName();
1084 const std::string gesture_total_latency_histogram_name =
1085 base::JoinString({histogram_base_name, gesture_type_name,
1086 total_latency_stage_name},
1088 ReportEventLatencyMetric(gesture_total_latency_histogram_name,
1089 gesture_histogram_index, total_latency);
1092 // Finally, report total latency up to presentation for all event types in
1093 // a single aggregate histogram.
1094 const std::string aggregate_total_latency_histogram_name =
1096 {kEventLatencyBaseHistogramName, total_latency_stage_name}, ".");
1097 UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
1098 aggregate_total_latency_histogram_name, total_latency,
1099 kEventLatencyHistogramMin, kEventLatencyHistogramMax,
1100 kEventLatencyHistogramBucketCount);
1103 if (global_trackers_.event_latency_tracker) {
1104 EventLatencyTracker::LatencyData& latency_data =
1105 latencies.emplace_back(event_metrics->type(), total_latency);
1108 latency_data.input_type = scroll_metrics->scroll_type();
1109 else if (pinch_metrics)
1110 latency_data.input_type = pinch_metrics->pinch_type();
1114 if (!latencies.empty()) {
1115 DCHECK(global_trackers_.event_latency_tracker);
1116 global_trackers_.event_latency_tracker->ReportEventLatency(
1117 std::move(latencies));
1121 void CompositorFrameReporter::ReportCompositorLatencyTraceEvents(
1122 const FrameInfo& info) const {
1123 if (stage_history_.empty())
1126 if (info.IsDroppedAffectingSmoothness()) {
1127 devtools_instrumentation::DidDropSmoothnessFrame(
1128 layer_tree_host_id_, args_.frame_time, args_.frame_id.sequence_number,
1129 has_partial_update_);
1132 const auto trace_track =
1133 perfetto::Track(base::trace_event::GetNextGlobalTraceId());
1135 kTraceCategory, "PipelineReporter", trace_track, args_.frame_time,
1136 [&](perfetto::EventContext context) {
1137 using perfetto::protos::pbzero::ChromeFrameReporter;
1138 ChromeFrameReporter::State state;
1139 switch (info.final_state) {
1140 case FrameInfo::FrameFinalState::kPresentedAll:
1141 state = ChromeFrameReporter::STATE_PRESENTED_ALL;
1143 case FrameInfo::FrameFinalState::kPresentedPartialNewMain:
1144 case FrameInfo::FrameFinalState::kPresentedPartialOldMain:
1145 state = ChromeFrameReporter::STATE_PRESENTED_PARTIAL;
1147 case FrameInfo::FrameFinalState::kNoUpdateDesired:
1148 state = ChromeFrameReporter::STATE_NO_UPDATE_DESIRED;
1150 case FrameInfo::FrameFinalState::kDropped:
1151 state = ChromeFrameReporter::STATE_DROPPED;
1155 auto* reporter = context.event()->set_chrome_frame_reporter();
1156 reporter->set_state(state);
1157 reporter->set_frame_source(args_.frame_id.source_id);
1158 reporter->set_frame_sequence(args_.frame_id.sequence_number);
1159 reporter->set_layer_tree_host_id(layer_tree_host_id_);
1160 reporter->set_has_missing_content(info.has_missing_content);
1161 if (info.IsDroppedAffectingSmoothness()) {
1162 DCHECK(state == ChromeFrameReporter::STATE_DROPPED ||
1163 state == ChromeFrameReporter::STATE_PRESENTED_PARTIAL);
1165 reporter->set_affects_smoothness(info.IsDroppedAffectingSmoothness());
1166 ChromeFrameReporter::ScrollState scroll_state;
1167 switch (info.scroll_thread) {
1168 case FrameInfo::SmoothEffectDrivingThread::kMain:
1169 scroll_state = ChromeFrameReporter::SCROLL_MAIN_THREAD;
1171 case FrameInfo::SmoothEffectDrivingThread::kCompositor:
1172 scroll_state = ChromeFrameReporter::SCROLL_COMPOSITOR_THREAD;
1174 case FrameInfo::SmoothEffectDrivingThread::kUnknown:
1175 scroll_state = ChromeFrameReporter::SCROLL_NONE;
1178 reporter->set_scroll_state(scroll_state);
1179 reporter->set_has_main_animation(
1180 HasMainThreadAnimation(active_trackers_));
1181 reporter->set_has_compositor_animation(
1182 HasCompositorThreadAnimation(active_trackers_));
1184 bool has_smooth_input_main = false;
1185 for (const auto& event_metrics : events_metrics_) {
1186 has_smooth_input_main |= event_metrics->HasSmoothInputEvent();
1188 reporter->set_has_smooth_input_main(has_smooth_input_main);
1189 reporter->set_has_high_latency(
1190 (frame_termination_time_ - args_.frame_time) > kHighLatencyMin);
1193 reporter->set_frame_type(ChromeFrameReporter::FORKED);
1194 } else if (is_backfill_) {
1195 reporter->set_frame_type(ChromeFrameReporter::BACKFILL);
1198 for (auto stage : high_latency_substages_) {
1199 reporter->add_high_latency_contribution_stage(stage);
1202 // TODO(crbug.com/1086974): Set 'drop reason' if applicable.
1205 for (const auto& stage : stage_history_) {
1206 if (stage.start_time >= frame_termination_time_)
1208 DCHECK_GE(stage.end_time, stage.start_time);
1209 if (stage.start_time == stage.end_time)
1212 const char* stage_name = GetStageName(stage.stage_type);
1214 if (stage.stage_type == StageType::kSendBeginMainFrameToCommit) {
1216 kTraceCategory, perfetto::StaticString{stage_name}, trace_track,
1217 stage.start_time, [&](perfetto::EventContext context) {
1218 DCHECK(processed_blink_breakdown_);
1220 context.event<perfetto::protos::pbzero::ChromeTrackEvent>()
1221 ->set_send_begin_mainframe_to_commit_breakdown();
1222 for (auto it = processed_blink_breakdown_->CreateIterator();
1223 it.IsValid(); it.Advance()) {
1224 int64_t latency = it.GetLatency().InMicroseconds();
1225 int curr_breakdown = static_cast<int>(it.GetBreakdown());
1226 switch (curr_breakdown) {
1227 case static_cast<int>(BlinkBreakdown::kHandleInputEvents):
1228 reporter->set_handle_input_events_us(latency);
1230 case static_cast<int>(BlinkBreakdown::kAnimate):
1231 reporter->set_animate_us(latency);
1233 case static_cast<int>(BlinkBreakdown::kStyleUpdate):
1234 reporter->set_style_update_us(latency);
1236 case static_cast<int>(BlinkBreakdown::kLayoutUpdate):
1237 reporter->set_layout_update_us(latency);
1239 case static_cast<int>(BlinkBreakdown::kAccessibility):
1240 reporter->set_accessibility_update_us(latency);
1242 case static_cast<int>(BlinkBreakdown::kPrepaint):
1243 reporter->set_prepaint_us(latency);
1245 case static_cast<int>(BlinkBreakdown::kCompositingInputs):
1246 reporter->set_compositing_inputs_us(latency);
1248 case static_cast<int>(BlinkBreakdown::kPaint):
1249 reporter->set_paint_us(latency);
1251 case static_cast<int>(BlinkBreakdown::kCompositeCommit):
1252 reporter->set_composite_commit_us(latency);
1254 case static_cast<int>(BlinkBreakdown::kUpdateLayers):
1255 reporter->set_update_layers_us(latency);
1257 case static_cast<int>(BlinkBreakdown::kBeginMainSentToStarted):
1258 reporter->set_begin_main_sent_to_started_us(latency);
1266 TRACE_EVENT_BEGIN(kTraceCategory, perfetto::StaticString{stage_name},
1267 trace_track, stage.start_time);
1270 if (stage.stage_type ==
1271 StageType::kSubmitCompositorFrameToPresentationCompositorFrame) {
1272 DCHECK(processed_viz_breakdown_);
1273 for (auto it = processed_viz_breakdown_->CreateIterator(true);
1274 it.IsValid(); it.Advance()) {
1275 base::TimeTicks start_time = it.GetStartTime();
1276 base::TimeTicks end_time = it.GetEndTime();
1277 if (start_time >= end_time)
1279 const char* breakdown_name = GetVizBreakdownName(it.GetBreakdown());
1280 TRACE_EVENT_BEGIN(kTraceCategory,
1281 perfetto::StaticString{breakdown_name}, trace_track,
1283 TRACE_EVENT_END(kTraceCategory, trace_track, end_time);
1286 TRACE_EVENT_END(kTraceCategory, trace_track, stage.end_time);
1289 TRACE_EVENT_END(kTraceCategory, trace_track, frame_termination_time_);
1292 void CompositorFrameReporter::ReportEventLatencyTraceEvents() const {
1293 // TODO(mohsen): This function is becoming large and there is concerns about
1294 // having this in the compositor critical path. crbug.com/1072740 is
1295 // considering doing the reporting off-thread, but as a short-term solution,
1296 // we should investigate whether we can skip this function entirely if tracing
1297 // is off and whether that has any positive impact or not.
1298 for (const auto& event_metrics : events_metrics_) {
1299 EventLatencyTracingRecorder::RecordEventLatencyTraceEvent(
1300 event_metrics.get(), frame_termination_time_, &stage_history_,
1301 processed_viz_breakdown_.get());
1305 base::TimeDelta CompositorFrameReporter::SumOfStageHistory() const {
1306 base::TimeDelta sum;
1307 for (const StageData& stage : stage_history_)
1308 sum += stage.end_time - stage.start_time;
1312 base::TimeTicks CompositorFrameReporter::Now() const {
1313 return tick_clock_->NowTicks();
1316 void CompositorFrameReporter::AdoptReporter(
1317 std::unique_ptr<CompositorFrameReporter> reporter) {
1318 // If |this| reporter is dependent on another reporter to decide about partial
1319 // update, then |this| should not have any such dependents.
1320 DCHECK(!partial_update_decider_);
1321 DCHECK(!partial_update_dependents_.empty());
1323 // The adoptee tracks a partial update. If it has metrics that depend on the
1324 // main thread update, move them into |this| reporter.
1325 AddEventsMetrics(reporter->TakeMainBlockedEventsMetrics());
1327 owned_partial_update_dependents_.push(std::move(reporter));
1328 DiscardOldPartialUpdateReporters();
1331 void CompositorFrameReporter::CalculateCompositorLatencyPrediction(
1332 CompositorLatencyInfo& previous_predictions,
1333 base::TimeDelta prediction_deviation_threshold) {
1334 // `stage_history_` should not be empty since we are calling this function
1335 // from DidPresentCompositorFrame(), which means there has to be some sort of
1337 DCHECK(!stage_history_.empty());
1339 // If the bad case of having `total_latency` of `previous_predictions` happens
1340 // then it would mess up the prediction calculation, therefore, we want to
1341 // reset the prediction by setting everything back to -1.
1342 if (previous_predictions.total_latency.is_zero())
1343 previous_predictions = CompositorLatencyInfo(base::Microseconds(-1));
1345 base::TimeDelta total_pipeline_latency =
1346 stage_history_.back().end_time - stage_history_[0].start_time;
1348 // Do not record current breakdown stages' duration if the total latency of
1349 // the current PipelineReporter is 0s. And no further predictions could be
1350 // made in this case.
1351 if (total_pipeline_latency.is_zero())
1354 processed_blink_breakdown_ = std::make_unique<ProcessedBlinkBreakdown>(
1355 blink_start_time_, begin_main_frame_start_, blink_breakdown_);
1356 processed_viz_breakdown_ =
1357 std::make_unique<ProcessedVizBreakdown>(viz_start_time_, viz_breakdown_);
1359 // Note that `current_stage_durations` would always have the same length as
1360 // `previous_predictions`, since each index represent the breakdown stages of
1361 // the PipelineReporter listed at enum class, StageType.
1362 CompositorLatencyInfo current_stage_durations(base::Microseconds(0));
1363 current_stage_durations.total_latency = total_pipeline_latency;
1365 for (auto stage : stage_history_) {
1366 if (stage.stage_type == StageType::kTotalLatency)
1368 base::TimeDelta substageLatency = stage.end_time - stage.start_time;
1369 current_stage_durations
1370 .top_level_stages[static_cast<int>(stage.stage_type)] = substageLatency;
1373 for (auto it = processed_blink_breakdown_->CreateIterator(); it.IsValid();
1375 current_stage_durations
1376 .blink_breakdown_stages[static_cast<int>(it.GetBreakdown())] =
1378 current_stage_durations.total_blink_latency += it.GetLatency();
1381 for (auto it = processed_viz_breakdown_->CreateIterator(true); it.IsValid();
1383 current_stage_durations
1384 .viz_breakdown_stages[static_cast<int>(it.GetBreakdown())] =
1386 current_stage_durations.total_viz_latency += it.GetDuration();
1389 // Do not record current pipeline details or update predictions if no frame
1391 if (current_stage_durations
1392 .top_level_stages[static_cast<int>(
1393 StageType::kSubmitCompositorFrameToPresentationCompositorFrame)]
1397 // The previous prediction is initialized to be -1, so check if the current
1398 // PipelineReporter is the first reporter ever to be calculated.
1399 if (previous_predictions.total_latency == base::Microseconds(-1)) {
1400 previous_predictions = current_stage_durations;
1402 if ((current_stage_durations.total_latency -
1403 previous_predictions.total_latency) >= prediction_deviation_threshold)
1404 FindHighLatencyAttribution(previous_predictions, current_stage_durations);
1406 for (int i = 0; i < kNumOfCompositorStages; i++) {
1407 previous_predictions.top_level_stages[i] =
1408 PredictLatency(previous_predictions.top_level_stages[i],
1409 current_stage_durations.top_level_stages[i]);
1411 previous_predictions.total_latency =
1412 PredictLatency(previous_predictions.total_latency,
1413 current_stage_durations.total_latency);
1415 if (!current_stage_durations.total_blink_latency.is_zero()) {
1416 for (int i = 0; i < kNumOfBlinkStages; i++) {
1417 previous_predictions.blink_breakdown_stages[i] =
1418 previous_predictions.total_blink_latency.is_zero()
1419 ? current_stage_durations.blink_breakdown_stages[i]
1421 previous_predictions.blink_breakdown_stages[i],
1422 current_stage_durations.blink_breakdown_stages[i]);
1424 previous_predictions.total_blink_latency =
1425 previous_predictions.total_blink_latency.is_zero()
1426 ? current_stage_durations.total_blink_latency
1427 : PredictLatency(previous_predictions.total_blink_latency,
1428 current_stage_durations.total_blink_latency);
1431 // TODO(crbug.com/1349930): implement check that ensure the prediction is
1432 // correct by checking if platform supports breakdown of the stage
1433 // SubmitCompositorFrameToPresentationCompositorFrame.SwapStartToSwapEnd,
1434 // then SwapStartToSwapEnd should always be 0s and data for breakdown of it
1435 // should always be available. (See enum class `VizBreakdown` for stage
1437 if (!current_stage_durations.total_viz_latency.is_zero()) {
1438 for (int i = 0; i < kNumOfVizStages; i++) {
1439 previous_predictions.viz_breakdown_stages[i] =
1440 previous_predictions.total_viz_latency.is_zero()
1441 ? current_stage_durations.viz_breakdown_stages[i]
1443 previous_predictions.viz_breakdown_stages[i],
1444 current_stage_durations.viz_breakdown_stages[i]);
1446 previous_predictions.total_viz_latency =
1447 previous_predictions.total_viz_latency.is_zero()
1448 ? current_stage_durations.total_viz_latency
1449 : PredictLatency(previous_predictions.total_viz_latency,
1450 current_stage_durations.total_viz_latency);
1455 void CompositorFrameReporter::CalculateEventLatencyPrediction(
1456 CompositorFrameReporter::EventLatencyInfo& predicted_event_latency,
1457 base::TimeDelta prediction_deviation_threshold) {
1458 if (events_metrics_.empty())
1461 // TODO(crbug.com/1334827): Explore calculating predictions for multiple
1462 // events. Currently only kGestureScrollUpdate event predictions
1463 // are being calculated, consider including other stages in future changes.
1464 auto event_it = base::ranges::find_if(
1465 events_metrics_, [](const std::unique_ptr<EventMetrics>& event) {
1467 event->type() == EventMetrics::EventType::kGestureScrollUpdate;
1469 if (event_it == events_metrics_.end())
1471 auto& event_metrics = *event_it;
1473 base::TimeTicks dispatch_start_time =
1474 event_metrics->GetDispatchStageTimestamp(
1475 EventMetrics::DispatchStage::kGenerated);
1477 // Determine the last valid stage in case kRendererMainFinished or
1478 // kRendererCompositorFinished stages do not exist, otherwise there is not
1479 // enough information for the prediction.
1480 EventMetrics::DispatchStage last_valid_stage =
1481 EventMetrics::DispatchStage::kGenerated;
1482 if (event_metrics->GetDispatchStageTimestamp(
1483 EventMetrics::DispatchStage::kRendererMainFinished) >
1484 dispatch_start_time) {
1485 last_valid_stage = EventMetrics::DispatchStage::kRendererMainFinished;
1486 } else if (event_metrics->GetDispatchStageTimestamp(
1487 EventMetrics::DispatchStage::kRendererCompositorFinished) >
1488 dispatch_start_time) {
1489 last_valid_stage = EventMetrics::DispatchStage::kRendererCompositorFinished;
1492 base::TimeTicks dispatch_end_time =
1493 event_metrics->GetDispatchStageTimestamp(last_valid_stage);
1494 base::TimeDelta total_dispatch_duration =
1495 dispatch_end_time - dispatch_start_time;
1496 if (total_dispatch_duration.is_negative())
1499 CompositorFrameReporter::EventLatencyInfo actual_event_latency(
1500 kNumDispatchStages, kNumOfCompositorStages);
1501 actual_event_latency.total_duration = base::Microseconds(0);
1503 // Determine dispatch stage durations.
1504 base::TimeTicks previous_timetick = dispatch_start_time;
1505 for (auto stage = EventMetrics::DispatchStage::kGenerated;
1506 stage <= last_valid_stage;
1507 stage = static_cast<EventMetrics::DispatchStage>(
1508 static_cast<int>(stage) + 1)) {
1509 if (stage != EventMetrics::DispatchStage::kGenerated) {
1510 base::TimeTicks current_timetick =
1511 event_metrics->GetDispatchStageTimestamp(stage);
1512 // Only update stage if the current_timetick is later than the
1513 // previous_timetick.
1514 if (current_timetick > previous_timetick) {
1515 base::TimeDelta stage_duration = current_timetick - previous_timetick;
1516 actual_event_latency.dispatch_durations[static_cast<int>(stage) - 1] =
1518 actual_event_latency.total_duration += stage_duration;
1519 previous_timetick = current_timetick;
1524 // Determine dispatch-to-compositor transition stage duration.
1525 auto stage_it = base::ranges::lower_bound(
1526 stage_history_, dispatch_end_time, {},
1527 &CompositorFrameReporter::StageData::start_time);
1528 if (stage_it != stage_history_.end()) {
1529 if (dispatch_end_time < stage_it->start_time) {
1530 base::TimeDelta stage_duration = stage_it->start_time - dispatch_end_time;
1531 actual_event_latency.transition_duration = stage_duration;
1532 actual_event_latency.total_duration += stage_duration;
1533 actual_event_latency.transition_name =
1534 EventLatencyTracingRecorder::GetDispatchToCompositorBreakdownName(
1535 last_valid_stage, stage_it->stage_type);
1539 // Determine compositor stage durations, which start from stage_it for
1541 for (auto stage = stage_it; stage != stage_history_.end(); stage++) {
1542 base::TimeDelta stage_duration = stage->end_time - stage->start_time;
1543 if (stage_duration.is_positive()) {
1544 actual_event_latency
1545 .compositor_durations[static_cast<int>(stage->stage_type)] =
1547 actual_event_latency.total_duration += stage_duration;
1551 // High latency attribution.
1552 if (predicted_event_latency.total_duration.is_positive() &&
1553 actual_event_latency.total_duration -
1554 predicted_event_latency.total_duration >=
1555 prediction_deviation_threshold) {
1556 FindEventLatencyAttribution(event_metrics.get(), predicted_event_latency,
1557 actual_event_latency);
1560 // Calculate new dispatch stage predictions.
1561 base::TimeDelta predicted_total_duration = base::Microseconds(0);
1562 for (int i = 0; i < kNumDispatchStages; i++) {
1563 if (actual_event_latency.dispatch_durations[i].is_positive()) {
1564 predicted_event_latency.dispatch_durations[i] = CalculateWeightedAverage(
1565 predicted_event_latency.dispatch_durations[i],
1566 actual_event_latency.dispatch_durations[i]);
1568 if (predicted_event_latency.dispatch_durations[i].is_positive()) {
1569 predicted_total_duration += predicted_event_latency.dispatch_durations[i];
1573 // Calculate new dispatch-to-compositor transition stage predictions.
1574 if (actual_event_latency.transition_duration.is_positive()) {
1575 predicted_event_latency.transition_duration =
1576 CalculateWeightedAverage(predicted_event_latency.transition_duration,
1577 actual_event_latency.transition_duration);
1578 if (predicted_event_latency.transition_duration.is_positive())
1579 predicted_total_duration += predicted_event_latency.transition_duration;
1582 // Calculate new compositor stage predictions.
1583 // TODO(crbug.com/1334827): Explore using existing PipelineReporter
1584 // predictions for the compositor stage.
1585 for (int i = 0; i < kNumOfCompositorStages; i++) {
1586 if (actual_event_latency.compositor_durations[i].is_positive()) {
1587 predicted_event_latency.compositor_durations[i] =
1588 CalculateWeightedAverage(
1589 predicted_event_latency.compositor_durations[i],
1590 actual_event_latency.compositor_durations[i]);
1592 if (predicted_event_latency.compositor_durations[i].is_positive()) {
1593 predicted_total_duration +=
1594 predicted_event_latency.compositor_durations[i];
1598 predicted_event_latency.total_duration = predicted_total_duration;
1601 void CompositorFrameReporter::SetPartialUpdateDecider(
1602 CompositorFrameReporter* decider) {
1604 DCHECK(partial_update_dependents_.empty());
1605 has_partial_update_ = true;
1606 partial_update_decider_ = decider->GetWeakPtr();
1607 decider->partial_update_dependents_.push(GetWeakPtr());
1610 void CompositorFrameReporter::DiscardOldPartialUpdateReporters() {
1611 DCHECK_LE(owned_partial_update_dependents_.size(),
1612 partial_update_dependents_.size());
1613 // Remove old owned partial update dependents if there are too many.
1614 while (owned_partial_update_dependents_.size() >
1615 kMaxOwnedPartialUpdateDependents) {
1616 auto& dependent = owned_partial_update_dependents_.front();
1617 dependent->set_has_partial_update(false);
1618 owned_partial_update_dependents_.pop();
1619 discarded_partial_update_dependents_count_++;
1622 // Remove dependent reporters from the front of `partial_update_dependents_`
1623 // queue if they are already destroyed.
1624 while (!partial_update_dependents_.empty() &&
1625 !partial_update_dependents_.front()) {
1626 partial_update_dependents_.pop();
1630 base::WeakPtr<CompositorFrameReporter> CompositorFrameReporter::GetWeakPtr() {
1631 return weak_factory_.GetWeakPtr();
1634 FrameInfo CompositorFrameReporter::GenerateFrameInfo() const {
1635 FrameFinalState final_state = FrameFinalState::kNoUpdateDesired;
1636 auto smooth_thread = smooth_thread_;
1637 auto scrolling_thread = scrolling_thread_;
1639 switch (frame_termination_status_) {
1640 case FrameTerminationStatus::kPresentedFrame:
1641 if (has_partial_update_) {
1642 final_state = is_accompanied_by_main_thread_update_
1643 ? FrameFinalState::kPresentedPartialNewMain
1644 : FrameFinalState::kPresentedPartialOldMain;
1646 final_state = FrameFinalState::kPresentedAll;
1650 case FrameTerminationStatus::kDidNotPresentFrame:
1651 case FrameTerminationStatus::kReplacedByNewReporter:
1652 final_state = FrameFinalState::kDropped;
1655 case FrameTerminationStatus::kDidNotProduceFrame: {
1656 const bool no_update_expected_from_main =
1657 frame_skip_reason_.has_value() &&
1658 frame_skip_reason() == FrameSkippedReason::kNoDamage;
1659 const bool no_update_expected_from_compositor =
1660 !has_partial_update_ && frame_skip_reason_.has_value() &&
1661 frame_skip_reason() == FrameSkippedReason::kWaitingOnMain;
1662 const bool draw_is_throttled =
1663 frame_skip_reason_.has_value() &&
1664 frame_skip_reason() == FrameSkippedReason::kDrawThrottled;
1666 if (!no_update_expected_from_main &&
1667 !no_update_expected_from_compositor) {
1668 final_state = FrameFinalState::kDropped;
1669 } else if (draw_is_throttled) {
1670 final_state = FrameFinalState::kDropped;
1672 final_state = FrameFinalState::kNoUpdateDesired;
1675 // If the compositor-thread is running an animation, and it ends with
1676 // 'did not produce frame', then that implies that the compositor
1677 // animation did not cause any visual changes. So for such cases, update
1678 // the `smooth_thread` for the FrameInfo created to exclude the compositor
1679 // thread. However, it is important to keep `final_state` unchanged,
1680 // because the main-thread update (if any) did get dropped.
1681 if (frame_skip_reason_.has_value() &&
1682 frame_skip_reason() == FrameSkippedReason::kWaitingOnMain) {
1683 if (smooth_thread == SmoothThread::kSmoothBoth) {
1684 smooth_thread = SmoothThread::kSmoothMain;
1685 } else if (smooth_thread == SmoothThread::kSmoothCompositor) {
1686 smooth_thread = SmoothThread::kSmoothNone;
1689 if (scrolling_thread ==
1690 FrameInfo::SmoothEffectDrivingThread::kCompositor) {
1691 scrolling_thread = FrameInfo::SmoothEffectDrivingThread::kUnknown;
1698 case FrameTerminationStatus::kUnknown:
1703 info.final_state = final_state;
1704 info.smooth_thread = smooth_thread;
1705 info.scroll_thread = scrolling_thread;
1706 info.has_missing_content = has_missing_content_;
1708 if (frame_skip_reason_.has_value() &&
1709 frame_skip_reason() == FrameSkippedReason::kNoDamage) {
1710 // If the frame was explicitly skipped because of 'no damage', then that
1711 // means this frame contains the response ('no damage') from the
1713 info.main_thread_response = FrameInfo::MainThreadResponse::kIncluded;
1714 } else if (partial_update_dependents_.size() > 0) {
1715 // Only a frame containing a response from the main-thread can have
1716 // dependent reporters.
1717 info.main_thread_response = FrameInfo::MainThreadResponse::kIncluded;
1718 } else if (begin_main_frame_start_.is_null() ||
1719 (frame_skip_reason_.has_value() &&
1720 frame_skip_reason() == FrameSkippedReason::kWaitingOnMain)) {
1721 // If 'begin main frame' never started, or if it started, but it
1722 // had to be skipped because it was waiting on the main-thread,
1723 // then the main-thread update is missing from this reporter.
1724 info.main_thread_response = FrameInfo::MainThreadResponse::kMissing;
1726 info.main_thread_response = FrameInfo::MainThreadResponse::kIncluded;
1729 if (!stage_history_.empty()) {
1730 const auto& stage = stage_history_.back();
1731 if (stage.stage_type == StageType::kTotalLatency) {
1732 DCHECK_EQ(frame_termination_time_ - args_.frame_time,
1733 stage.end_time - stage.start_time);
1734 info.total_latency = frame_termination_time_ - args_.frame_time;
1741 void CompositorFrameReporter::FindHighLatencyAttribution(
1742 CompositorLatencyInfo& previous_predictions,
1743 CompositorLatencyInfo& current_stage_durations) {
1744 if (previous_predictions.total_latency.is_zero() ||
1745 current_stage_durations.total_latency.is_zero())
1748 double contribution_change = -1;
1749 double highest_contribution_change = -1;
1750 std::vector<int> highest_contribution_change_index;
1751 std::vector<int> highest_blink_contribution_change_index;
1752 std::vector<int> highest_viz_contribution_change_index;
1754 for (int i = 0; i < kNumOfCompositorStages; i++) {
1756 case static_cast<int>(StageType::kSendBeginMainFrameToCommit):
1757 if (current_stage_durations.top_level_stages[i].is_zero() ||
1758 previous_predictions.total_blink_latency.is_zero() ||
1759 current_stage_durations.total_blink_latency.is_zero())
1762 for (int j = 0; j < kNumOfBlinkStages; j++) {
1763 contribution_change =
1764 (current_stage_durations.blink_breakdown_stages[j] /
1765 current_stage_durations.total_latency) -
1766 (previous_predictions.blink_breakdown_stages[j] /
1767 previous_predictions.total_latency);
1769 if (contribution_change > highest_contribution_change) {
1770 highest_contribution_change = contribution_change;
1771 highest_contribution_change_index.clear();
1772 highest_viz_contribution_change_index.clear();
1773 highest_blink_contribution_change_index = {j};
1774 } else if (std::abs(contribution_change -
1775 highest_contribution_change) < kEpsilon) {
1776 highest_blink_contribution_change_index.push_back(j);
1781 case static_cast<int>(
1782 StageType::kSubmitCompositorFrameToPresentationCompositorFrame):
1783 if (current_stage_durations.top_level_stages[i].is_zero() ||
1784 previous_predictions.total_viz_latency.is_zero() ||
1785 current_stage_durations.total_viz_latency.is_zero())
1788 for (int j = 0; j < kNumOfVizStages; j++) {
1789 contribution_change =
1790 (current_stage_durations.viz_breakdown_stages[j] /
1791 current_stage_durations.total_latency) -
1792 (previous_predictions.viz_breakdown_stages[j] /
1793 previous_predictions.total_latency);
1795 if (contribution_change > highest_contribution_change) {
1796 highest_contribution_change = contribution_change;
1797 highest_contribution_change_index.clear();
1798 highest_blink_contribution_change_index.clear();
1799 highest_viz_contribution_change_index = {j};
1800 } else if (std::abs(contribution_change -
1801 highest_contribution_change) < kEpsilon) {
1802 highest_viz_contribution_change_index.push_back(j);
1808 contribution_change = (current_stage_durations.top_level_stages[i] /
1809 current_stage_durations.total_latency) -
1810 (previous_predictions.top_level_stages[i] /
1811 previous_predictions.total_latency);
1813 if (contribution_change > highest_contribution_change) {
1814 highest_contribution_change = contribution_change;
1815 highest_blink_contribution_change_index.clear();
1816 highest_viz_contribution_change_index.clear();
1817 highest_contribution_change_index = {i};
1818 } else if (std::abs(contribution_change - highest_contribution_change) <
1820 highest_contribution_change_index.push_back(i);
1826 // It is not expensive to go through vector of indexes again since it is
1827 // usually very small (possibilities of breakdown stages having the same
1828 // change contribution is small).
1829 for (auto index : highest_contribution_change_index) {
1830 high_latency_substages_.push_back(
1831 GetStageName(static_cast<StageType>(index)));
1833 for (auto index : highest_blink_contribution_change_index) {
1834 high_latency_substages_.push_back(
1835 GetStageName(StageType::kSendBeginMainFrameToCommit, absl::nullopt,
1836 static_cast<BlinkBreakdown>(index)));
1838 for (auto index : highest_viz_contribution_change_index) {
1839 high_latency_substages_.push_back(GetStageName(
1840 StageType::kSubmitCompositorFrameToPresentationCompositorFrame,
1841 static_cast<VizBreakdown>(index)));
1845 void CompositorFrameReporter::FindEventLatencyAttribution(
1846 EventMetrics* event_metrics,
1847 CompositorFrameReporter::EventLatencyInfo& predicted_event_latency,
1848 CompositorFrameReporter::EventLatencyInfo& actual_event_latency) {
1852 std::vector<std::string> high_latency_stages;
1853 double contribution_change = -1;
1854 double highest_contribution_change = -1;
1856 // Check dispatch stage change
1857 EventMetrics::DispatchStage dispatch_stage =
1858 EventMetrics::DispatchStage::kGenerated;
1859 base::TimeTicks dispatch_timestamp =
1860 event_metrics->GetDispatchStageTimestamp(dispatch_stage);
1861 while (dispatch_stage != EventMetrics::DispatchStage::kMaxValue) {
1862 DCHECK(!dispatch_timestamp.is_null());
1863 auto end_stage = static_cast<EventMetrics::DispatchStage>(
1864 static_cast<int>(dispatch_stage) + 1);
1865 base::TimeTicks end_timestamp =
1866 event_metrics->GetDispatchStageTimestamp(end_stage);
1867 while (end_timestamp.is_null() &&
1868 end_stage != EventMetrics::DispatchStage::kMaxValue) {
1869 end_stage = static_cast<EventMetrics::DispatchStage>(
1870 static_cast<int>(end_stage) + 1);
1871 end_timestamp = event_metrics->GetDispatchStageTimestamp(end_stage);
1873 if (end_timestamp.is_null())
1876 contribution_change =
1877 (actual_event_latency
1878 .dispatch_durations[static_cast<int>(end_stage) - 1] /
1879 actual_event_latency.total_duration) -
1880 (predicted_event_latency
1881 .dispatch_durations[static_cast<int>(end_stage) - 1] /
1882 predicted_event_latency.total_duration);
1883 std::string dispatch_stage_name =
1884 EventLatencyTracingRecorder::GetDispatchBreakdownName(dispatch_stage,
1886 highest_contribution_change = DetermineHighestContribution(
1887 contribution_change, highest_contribution_change, dispatch_stage_name,
1888 high_latency_stages);
1890 dispatch_stage = end_stage;
1891 dispatch_timestamp = end_timestamp;
1894 // Check dispatch-to-compositor stage change
1895 contribution_change = (actual_event_latency.transition_duration /
1896 actual_event_latency.total_duration) -
1897 (predicted_event_latency.transition_duration /
1898 predicted_event_latency.total_duration);
1899 highest_contribution_change = DetermineHighestContribution(
1900 contribution_change, highest_contribution_change,
1901 actual_event_latency.transition_name, high_latency_stages);
1903 // Check compositor stage change
1904 for (int i = 0; i < kNumOfCompositorStages; i++) {
1905 contribution_change = (actual_event_latency.compositor_durations[i] /
1906 actual_event_latency.total_duration) -
1907 (predicted_event_latency.compositor_durations[i] /
1908 predicted_event_latency.total_duration);
1909 highest_contribution_change = DetermineHighestContribution(
1910 contribution_change, highest_contribution_change,
1911 GetStageName(static_cast<StageType>(i)), high_latency_stages);
1914 for (auto stage : high_latency_stages) {
1915 event_metrics->SetHighLatencyStage(stage);