diff options
Diffstat (limited to 'chromium/cc/metrics/compositor_frame_reporter.cc')
| -rw-r--r-- | chromium/cc/metrics/compositor_frame_reporter.cc | 250 |
1 files changed, 153 insertions, 97 deletions
diff --git a/chromium/cc/metrics/compositor_frame_reporter.cc b/chromium/cc/metrics/compositor_frame_reporter.cc index 560bc2932fc..cb494e657b7 100644 --- a/chromium/cc/metrics/compositor_frame_reporter.cc +++ b/chromium/cc/metrics/compositor_frame_reporter.cc @@ -15,19 +15,15 @@ namespace cc { namespace { -// When considering if a time is abnormal, compare the stage execution -// time to this percentile from the previous times of the same stage. -constexpr double kAbnormalityPercentile = 95; - -// Use for determining abnormal execution times. If the sample size is less -// than this then don't check for abnormal execution time. -constexpr size_t kMinimumTimeDeltaSampleSize = 20; +using StageType = CompositorFrameReporter::StageType; +using VizBreakdown = CompositorFrameReporter::VizBreakdown; constexpr int kMissedFrameReportTypeCount = static_cast<int>(CompositorFrameReporter::MissedFrameReportTypes:: kMissedFrameReportTypeCount); -constexpr int kStageTypeCount = - static_cast<int>(CompositorFrameReporter::StageType::kStageTypeCount); +constexpr int kStageTypeCount = static_cast<int>(StageType::kStageTypeCount); +constexpr int kAllBreakdownCount = + static_cast<int>(VizBreakdown::kBreakdownCount); // For each possible FrameSequenceTrackerType there will be a UMA histogram // plus one for general case. constexpr int kFrameSequenceTrackerTypeCount = @@ -35,16 +31,37 @@ constexpr int kFrameSequenceTrackerTypeCount = // Names for CompositorFrameReporter::StageType, which should be updated in case // of changes to the enum. -constexpr const char* kStageNames[]{ - "BeginImplFrameToSendBeginMainFrame", - "SendBeginMainFrameToCommit", - "Commit", - "EndCommitToActivation", - "Activation", - "EndActivateToSubmitCompositorFrame", - "SubmitCompositorFrameToPresentationCompositorFrame", - "TotalLatency"}; -static_assert(sizeof(kStageNames) / sizeof(kStageNames[0]) == kStageTypeCount, +constexpr const char* kStageNames[] = { + [static_cast<int>(StageType::kBeginImplFrameToSendBeginMainFrame)] = + "BeginImplFrameToSendBeginMainFrame", + [static_cast<int>(StageType::kSendBeginMainFrameToCommit)] = + "SendBeginMainFrameToCommit", + [static_cast<int>(StageType::kCommit)] = "Commit", + [static_cast<int>(StageType::kEndCommitToActivation)] = + "EndCommitToActivation", + [static_cast<int>(StageType::kActivation)] = "Activation", + [static_cast<int>(StageType::kEndActivateToSubmitCompositorFrame)] = + "EndActivateToSubmitCompositorFrame", + [static_cast<int>( + StageType::kSubmitCompositorFrameToPresentationCompositorFrame)] = + "SubmitCompositorFrameToPresentationCompositorFrame", + [static_cast<int>(StageType::kTotalLatency)] = "TotalLatency", + [static_cast<int>(VizBreakdown::kSubmitToReceiveCompositorFrame) + + kStageTypeCount] = + "SubmitCompositorFrameToPresentationCompositorFrame." + "SubmitToReceiveCompositorFrame", + [static_cast<int>(VizBreakdown::kReceivedCompositorFrameToStartDraw) + + kStageTypeCount] = + "SubmitCompositorFrameToPresentationCompositorFrame." + "ReceivedCompositorFrameToStartDraw", + [static_cast<int>(VizBreakdown::kStartDrawToSwapEnd) + kStageTypeCount] = + "SubmitCompositorFrameToPresentationCompositorFrame.StartDrawToSwapEnd", + [static_cast<int>(VizBreakdown::kSwapEndToPresentationCompositorFrame) + + kStageTypeCount] = + "SubmitCompositorFrameToPresentationCompositorFrame." + "SwapEndToPresentationCompositorFrame"}; +static_assert(sizeof(kStageNames) / sizeof(kStageNames[0]) == + kStageTypeCount + kAllBreakdownCount, "Compositor latency stages has changed."); // Names for CompositorFrameReporter::MissedFrameReportTypes, which should be @@ -59,23 +76,24 @@ static_assert(sizeof(kReportTypeNames) / sizeof(kReportTypeNames[0]) == // This value should be recalculate in case of changes to the number of values // in CompositorFrameReporter::MissedFrameReportTypes or in // CompositorFrameReporter::StageType -constexpr int kMaxHistogramIndex = 2 * kMissedFrameReportTypeCount * +constexpr int kMaxHistogramIndex = kMissedFrameReportTypeCount * kFrameSequenceTrackerTypeCount * - kStageTypeCount; + (kStageTypeCount + kAllBreakdownCount); constexpr int kHistogramMin = 1; constexpr int kHistogramMax = 350000; constexpr int kHistogramBucketCount = 50; -std::string HistogramName(const char* compositor_type, - const int report_type_index, +std::string HistogramName(const int report_type_index, const int frame_sequence_tracker_type_index, const int stage_type_index) { - std::string tracker_type_name = FrameSequenceTracker:: + DCHECK_LE(frame_sequence_tracker_type_index, + FrameSequenceTrackerType::kMaxType); + const char* tracker_type_name = FrameSequenceTracker:: kFrameSequenceTrackerTypeNames[frame_sequence_tracker_type_index]; - if (!tracker_type_name.empty()) - tracker_type_name += "."; - return base::StrCat({compositor_type, "CompositorLatency.", + DCHECK(tracker_type_name); + return base::StrCat({"CompositorLatency.", kReportTypeNames[report_type_index], tracker_type_name, + *tracker_type_name ? "." : "", kStageNames[stage_type_index]}); } } // namespace @@ -93,14 +111,20 @@ CompositorFrameReporter::~CompositorFrameReporter() { TerminateReporter(); } +CompositorFrameReporter::StageData::StageData() = default; +CompositorFrameReporter::StageData::StageData(StageType stage_type, + base::TimeTicks start_time, + base::TimeTicks end_time) + : stage_type(stage_type), start_time(start_time), end_time(end_time) {} +CompositorFrameReporter::StageData::StageData(const StageData&) = default; +CompositorFrameReporter::StageData::~StageData() = default; + void CompositorFrameReporter::StartStage( CompositorFrameReporter::StageType stage_type, - base::TimeTicks start_time, - RollingTimeDeltaHistory* stage_time_delta_history) { + base::TimeTicks start_time) { EndCurrentStage(start_time); current_stage_.stage_type = stage_type; current_stage_.start_time = start_time; - current_stage_.time_delta_history = stage_time_delta_history; int stage_type_index = static_cast<int>(current_stage_.stage_type); CHECK_LT(stage_type_index, static_cast<int>(StageType::kStageTypeCount)); CHECK_GE(stage_type_index, 0); @@ -113,9 +137,8 @@ void CompositorFrameReporter::EndCurrentStage(base::TimeTicks end_time) { if (current_stage_.start_time == base::TimeTicks()) return; current_stage_.end_time = end_time; - stage_history_.emplace_back(current_stage_); + stage_history_.push_back(current_stage_); current_stage_.start_time = base::TimeTicks(); - current_stage_.time_delta_history = nullptr; } void CompositorFrameReporter::MissedSubmittedFrame() { @@ -130,8 +153,27 @@ void CompositorFrameReporter::TerminateFrame( EndCurrentStage(frame_termination_time_); } +void CompositorFrameReporter::OnFinishImplFrame(base::TimeTicks timestamp) { + DCHECK(!did_finish_impl_frame_); + + did_finish_impl_frame_ = true; + impl_frame_finish_time_ = timestamp; +} + +void CompositorFrameReporter::OnAbortBeginMainFrame() { + did_abort_main_frame_ = false; +} + +void CompositorFrameReporter::SetVizBreakdown( + const viz::FrameTimingDetails& viz_breakdown) { + DCHECK(current_stage_.viz_breakdown.received_compositor_frame_timestamp + .is_null()); + current_stage_.viz_breakdown = viz_breakdown; +} + void CompositorFrameReporter::TerminateReporter() { - DCHECK_EQ(current_stage_.start_time, base::TimeTicks()); + if (frame_termination_status_ != FrameTerminationStatus::kUnknown) + DCHECK_EQ(current_stage_.start_time, base::TimeTicks()); bool report_latency = false; const char* termination_status_str = nullptr; switch (frame_termination_status_) { @@ -140,25 +182,27 @@ void CompositorFrameReporter::TerminateReporter() { termination_status_str = "presented_frame"; break; case FrameTerminationStatus::kDidNotPresentFrame: + report_latency = true; + MissedSubmittedFrame(); termination_status_str = "did_not_present_frame"; break; case FrameTerminationStatus::kMainFrameAborted: termination_status_str = "main_frame_aborted"; break; case FrameTerminationStatus::kReplacedByNewReporter: + report_latency = true; + MissedSubmittedFrame(); termination_status_str = "replaced_by_new_reporter_at_same_stage"; break; case FrameTerminationStatus::kDidNotProduceFrame: termination_status_str = "did_not_produce_frame"; break; case FrameTerminationStatus::kUnknown: - NOTREACHED(); + termination_status_str = "terminated_before_ending"; break; } - const char* submission_status_str = submitted_frame_missed_deadline_ ? "missed_frame" : "non_missed_frame"; - TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP2( "cc,benchmark", "PipelineReporter", this, frame_termination_time_, "termination_status", TRACE_STR_COPY(termination_status_str), @@ -168,9 +212,9 @@ void CompositorFrameReporter::TerminateReporter() { // Only report histograms if the frame was presented. if (report_latency) { DCHECK(stage_history_.size()); - stage_history_.emplace_back( - StageData{StageType::kTotalLatency, stage_history_.front().start_time, - stage_history_.back().end_time, nullptr}); + stage_history_.emplace_back(StageType::kTotalLatency, + stage_history_.front().start_time, + stage_history_.back().end_time); ReportStageHistograms(submitted_frame_missed_deadline_); } } @@ -182,91 +226,103 @@ void CompositorFrameReporter::ReportStageHistograms(bool missed_frame) const { : CompositorFrameReporter::MissedFrameReportTypes::kNonMissedFrame; for (const StageData& stage : stage_history_) { - base::TimeDelta stage_delta = stage.end_time - stage.start_time; - ReportHistogram(report_type, FrameSequenceTrackerType::kMaxType, - stage.stage_type, stage_delta); + ReportStageHistogramWithBreakdown( + report_type, FrameSequenceTrackerType::kMaxType, stage); for (const auto& frame_sequence_tracker_type : *active_trackers_) { - ReportHistogram(report_type, frame_sequence_tracker_type, - stage.stage_type, stage_delta); + // Report stage breakdowns. + ReportStageHistogramWithBreakdown(report_type, + frame_sequence_tracker_type, stage); } + } +} - if (!stage.time_delta_history) - continue; - - if (!missed_frame) { - stage.time_delta_history->InsertSample(stage_delta); - } else { - // If enough sample data is recorded compare the stage duration with the - // known normal stage duration and if it's higher than normal, report the - // difference. - if (stage.time_delta_history->sample_count() >= - kMinimumTimeDeltaSampleSize) { - base::TimeDelta time_upper_limit = GetStateNormalUpperLimit(stage); - if (stage_delta > time_upper_limit) { - // This ReportHistogram reports the latency of all - // frame_sequence_tracker_types(interactions) combined. - auto current_report_type = CompositorFrameReporter:: - MissedFrameReportTypes::kMissedFrameLatencyIncrease; - ReportHistogram(current_report_type, - FrameSequenceTrackerType::kMaxType, stage.stage_type, - stage_delta - time_upper_limit); - - for (const auto& frame_sequence_tracker_type : *active_trackers_) { - ReportHistogram(current_report_type, frame_sequence_tracker_type, - stage.stage_type, stage_delta - time_upper_limit); - } - } - } - - // In case of a missing frame, remove a sample from the recorded normal - // stages. This invalidates the recorded normal durations if at a point - // all frames start missing for a while. - stage.time_delta_history->RemoveOldestSample(); +void CompositorFrameReporter::ReportStageHistogramWithBreakdown( + CompositorFrameReporter::MissedFrameReportTypes report_type, + FrameSequenceTrackerType frame_sequence_tracker_type, + CompositorFrameReporter::StageData stage) const { + base::TimeDelta stage_delta = stage.end_time - stage.start_time; + ReportHistogram(report_type, frame_sequence_tracker_type, + static_cast<int>(stage.stage_type), stage_delta); + switch (stage.stage_type) { + case StageType::kSubmitCompositorFrameToPresentationCompositorFrame: { + ReportVizBreakdown(report_type, frame_sequence_tracker_type, stage); + break; } + default: + break; } } +void CompositorFrameReporter::ReportVizBreakdown( + CompositorFrameReporter::MissedFrameReportTypes report_type, + FrameSequenceTrackerType frame_sequence_tracker_type, + CompositorFrameReporter::StageData stage) const { + // Check if viz_breakdown is set. + if (stage.viz_breakdown.received_compositor_frame_timestamp.is_null()) + return; + + int index_origin = static_cast<int>(StageType::kStageTypeCount); + base::TimeDelta submit_to_receive_compositor_frame_delta = + stage.viz_breakdown.received_compositor_frame_timestamp - + stage.start_time; + ReportHistogram(report_type, frame_sequence_tracker_type, index_origin, + submit_to_receive_compositor_frame_delta); + + if (stage.viz_breakdown.draw_start_timestamp.is_null()) + return; + base::TimeDelta received_compositor_frame_to_start_draw_delta = + stage.viz_breakdown.draw_start_timestamp - + stage.viz_breakdown.received_compositor_frame_timestamp; + ReportHistogram(report_type, frame_sequence_tracker_type, index_origin + 1, + received_compositor_frame_to_start_draw_delta); + + if (stage.viz_breakdown.swap_timings.is_null()) + return; + base::TimeDelta start_draw_to_swap_end_delta = + stage.viz_breakdown.swap_timings.swap_end - + stage.viz_breakdown.draw_start_timestamp; + + ReportHistogram(report_type, frame_sequence_tracker_type, index_origin + 2, + start_draw_to_swap_end_delta); + + base::TimeDelta swap_end_to_presentation_compositor_frame_delta = + stage.end_time - stage.viz_breakdown.swap_timings.swap_end; + + ReportHistogram(report_type, frame_sequence_tracker_type, index_origin + 3, + swap_end_to_presentation_compositor_frame_delta); +} + void CompositorFrameReporter::ReportHistogram( CompositorFrameReporter::MissedFrameReportTypes report_type, FrameSequenceTrackerType frame_sequence_tracker_type, - CompositorFrameReporter::StageType stage_type, + const int stage_type_index, base::TimeDelta time_delta) const { const int report_type_index = static_cast<int>(report_type); - const int stage_type_index = static_cast<int>(stage_type); const int frame_sequence_tracker_type_index = static_cast<int>(frame_sequence_tracker_type); const int histogram_index = - ((stage_type_index * kFrameSequenceTrackerTypeCount + - frame_sequence_tracker_type_index) * - kMissedFrameReportTypeCount + - report_type_index) * - 2 + - (is_single_threaded_ ? 1 : 0); - - CHECK_LT(stage_type_index, kStageTypeCount); + (stage_type_index * kFrameSequenceTrackerTypeCount + + frame_sequence_tracker_type_index) * + kMissedFrameReportTypeCount + + report_type_index; + + CHECK_LT(stage_type_index, kStageTypeCount + kAllBreakdownCount); CHECK_GE(stage_type_index, 0); CHECK_LT(report_type_index, kMissedFrameReportTypeCount); CHECK_GE(report_type_index, 0); CHECK_LT(histogram_index, kMaxHistogramIndex); CHECK_GE(histogram_index, 0); - const char* compositor_type = is_single_threaded_ ? "SingleThreaded" : ""; - STATIC_HISTOGRAM_POINTER_GROUP( - HistogramName(compositor_type, report_type_index, - frame_sequence_tracker_type_index, stage_type_index), + HistogramName(report_type_index, frame_sequence_tracker_type_index, + stage_type_index), histogram_index, kMaxHistogramIndex, AddTimeMicrosecondsGranularity(time_delta), base::Histogram::FactoryGet( - HistogramName(compositor_type, report_type_index, - frame_sequence_tracker_type_index, stage_type_index), + HistogramName(report_type_index, frame_sequence_tracker_type_index, + stage_type_index), kHistogramMin, kHistogramMax, kHistogramBucketCount, base::HistogramBase::kUmaTargetedHistogramFlag)); } - -base::TimeDelta CompositorFrameReporter::GetStateNormalUpperLimit( - const StageData& stage) const { - return stage.time_delta_history->Percentile(kAbnormalityPercentile); -} } // namespace cc |