| // Copyright 2019 The Chromium Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| #include "cc/scheduler/compositor_frame_reporter.h" |
| |
| #include <string> |
| |
| #include "base/metrics/histogram_macros.h" |
| #include "base/strings/stringprintf.h" |
| #include "base/trace_event/trace_event.h" |
| #include "cc/base/rolling_time_delta_history.h" |
| |
| 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. |
| static 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. |
| static constexpr size_t kMinimumTimeDeltaSampleSize = 20; |
| |
| static constexpr int kMissedFrameReportTypeCount = |
| static_cast<int>(CompositorFrameReporter::MissedFrameReportTypes:: |
| kMissedFrameReportTypeCount); |
| static constexpr int kStageTypeCount = |
| static_cast<int>(CompositorFrameReporter::StageType::kStageTypeCount); |
| |
| // 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", |
| "TotalLatency"}; |
| static_assert(sizeof(kStageNames) / sizeof(kStageNames[0]) == kStageTypeCount, |
| "Compositor latency stages has changed."); |
| |
| // Names for CompositorFrameReporter::MissedFrameReportTypes, which should be |
| // updated in case of changes to the enum. |
| constexpr const char* kReportTypeNames[]{"", "MissedFrame.", |
| "MissedFrameLatencyIncrease."}; |
| static_assert(sizeof(kReportTypeNames) / sizeof(kReportTypeNames[0]) == |
| kMissedFrameReportTypeCount, |
| "Compositor latency report types has changed."); |
| |
| // This value should be recalculate in case of changes to the number of values |
| // in CompositorFrameReporter::MissedFrameReportTypes or in |
| // CompositorFrameReporter::StageType |
| static constexpr int kMaxHistogramIndex = |
| 2 * kMissedFrameReportTypeCount * kStageTypeCount; |
| static constexpr int kHistogramMin = 1; |
| static constexpr int kHistogramMax = 350000; |
| static constexpr int kHistogramBucketCount = 50; |
| } // namespace |
| |
| CompositorFrameReporter::CompositorFrameReporter(bool is_single_threaded) |
| : is_single_threaded_(is_single_threaded) { |
| TRACE_EVENT_ASYNC_BEGIN1("cc,benchmark", "PipelineReporter", this, |
| "is_single_threaded", is_single_threaded); |
| } |
| |
| CompositorFrameReporter::~CompositorFrameReporter() { |
| TerminateReporter(); |
| } |
| |
| void CompositorFrameReporter::StartStage( |
| CompositorFrameReporter::StageType stage_type, |
| base::TimeTicks start_time, |
| RollingTimeDeltaHistory* stage_time_delta_history) { |
| 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); |
| TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP0( |
| "cc,benchmark", "PipelineReporter", this, |
| TRACE_STR_COPY(kStageNames[stage_type_index]), start_time); |
| } |
| |
| 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_); |
| current_stage_.start_time = base::TimeTicks(); |
| current_stage_.time_delta_history = nullptr; |
| } |
| |
| void CompositorFrameReporter::TerminateFrame( |
| FrameTerminationStatus termination_status, |
| base::TimeTicks termination_time) { |
| frame_termination_status_ = termination_status; |
| frame_termination_time_ = termination_time; |
| EndCurrentStage(frame_termination_time_); |
| } |
| |
| void CompositorFrameReporter::TerminateReporter() { |
| DCHECK_EQ(current_stage_.start_time, base::TimeTicks()); |
| bool report_latency = false; |
| bool missed_frame = false; |
| const char* termination_status_str = nullptr; |
| switch (frame_termination_status_) { |
| case FrameTerminationStatus::kSubmittedFrame: |
| report_latency = true; |
| termination_status_str = "submitted_frame"; |
| break; |
| case FrameTerminationStatus::kSubmittedFrameMissedDeadline: |
| report_latency = true; |
| missed_frame = true; |
| termination_status_str = "missed_frame"; |
| break; |
| case FrameTerminationStatus::kMainFrameAborted: |
| termination_status_str = "main_frame_aborted"; |
| break; |
| case FrameTerminationStatus::kReplacedByNewReporter: |
| 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(); |
| break; |
| } |
| |
| TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP1( |
| "cc,benchmark", "PipelineReporter", this, frame_termination_time_, |
| "termination_status", TRACE_STR_COPY(termination_status_str)); |
| 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}); |
| ReportStageHistograms(missed_frame); |
| } |
| } |
| |
| void CompositorFrameReporter::ReportStageHistograms(bool missed_frame) const { |
| CompositorFrameReporter::MissedFrameReportTypes report_type = |
| missed_frame |
| ? CompositorFrameReporter::MissedFrameReportTypes::kMissedFrame |
| : CompositorFrameReporter::MissedFrameReportTypes::kNonMissedFrame; |
| |
| for (const StageData& stage : stage_history_) { |
| base::TimeDelta stage_delta = stage.end_time - stage.start_time; |
| ReportHistogram(report_type, stage.stage_type, stage_delta); |
| |
| 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) { |
| ReportHistogram(CompositorFrameReporter::MissedFrameReportTypes:: |
| kMissedFrameLatencyIncrease, |
| 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::ReportHistogram( |
| CompositorFrameReporter::MissedFrameReportTypes report_type, |
| CompositorFrameReporter::StageType stage_type, |
| 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 histogram_index = |
| (stage_type_index * kMissedFrameReportTypeCount + report_type_index) * 2 + |
| (is_single_threaded_ ? 1 : 0); |
| |
| CHECK_LT(stage_type_index, kStageTypeCount); |
| 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( |
| base::StringPrintf("%s%s%s%s", compositor_type, "CompositorLatency.", |
| kReportTypeNames[static_cast<int>(report_type)], |
| kStageNames[static_cast<int>(stage_type)]), |
| histogram_index, kMaxHistogramIndex, |
| AddTimeMicrosecondsGranularity(time_delta), |
| base::Histogram::FactoryGet( |
| base::StringPrintf("%s%s%s%s", compositor_type, "CompositorLatency.", |
| kReportTypeNames[static_cast<int>(report_type)], |
| kStageNames[static_cast<int>(stage_type)]), |
| kHistogramMin, kHistogramMax, kHistogramBucketCount, |
| base::HistogramBase::kUmaTargetedHistogramFlag)); |
| } |
| |
| base::TimeDelta CompositorFrameReporter::GetStateNormalUpperLimit( |
| const StageData& stage) const { |
| return stage.time_delta_history->Percentile(kAbnormalityPercentile); |
| } |
| } // namespace cc |