diff options
author | Allan Sandfeld Jensen <allan.jensen@qt.io> | 2020-10-12 14:27:29 +0200 |
---|---|---|
committer | Allan Sandfeld Jensen <allan.jensen@qt.io> | 2020-10-13 09:35:20 +0000 |
commit | c30a6232df03e1efbd9f3b226777b07e087a1122 (patch) | |
tree | e992f45784689f373bcc38d1b79a239ebe17ee23 /chromium/cc/metrics | |
parent | 7b5b123ac58f58ffde0f4f6e488bcd09aa4decd3 (diff) | |
download | qtwebengine-chromium-c30a6232df03e1efbd9f3b226777b07e087a1122.tar.gz |
BASELINE: Update Chromium to 85.0.4183.14085-based
Change-Id: Iaa42f4680837c57725b1344f108c0196741f6057
Reviewed-by: Allan Sandfeld Jensen <allan.jensen@qt.io>
Diffstat (limited to 'chromium/cc/metrics')
28 files changed, 1501 insertions, 858 deletions
diff --git a/chromium/cc/metrics/compositor_frame_reporter.cc b/chromium/cc/metrics/compositor_frame_reporter.cc index 13c15d9b1dd..c5b037edf4d 100644 --- a/chromium/cc/metrics/compositor_frame_reporter.cc +++ b/chromium/cc/metrics/compositor_frame_reporter.cc @@ -4,6 +4,7 @@ #include "cc/metrics/compositor_frame_reporter.h" +#include <algorithm> #include <memory> #include <string> #include <utility> @@ -11,10 +12,14 @@ #include "base/metrics/histogram_macros.h" #include "base/stl_util.h" #include "base/strings/strcat.h" +#include "base/time/time.h" #include "base/trace_event/trace_event.h" #include "cc/base/rolling_time_delta_history.h" +#include "cc/metrics/dropped_frame_counter.h" #include "cc/metrics/frame_sequence_tracker.h" #include "cc/metrics/latency_ukm_reporter.h" +#include "services/tracing/public/cpp/perfetto/macros.h" +#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_frame_reporter.pbzero.h" #include "ui/events/types/event_type.h" namespace cc { @@ -42,7 +47,8 @@ constexpr int kFrameSequenceTrackerTypeCount = static_cast<int>(FrameSequenceTrackerType::kMaxType) + 1; // Names for the viz breakdowns that are shown in trace as substages under -// PipelineReporter -> SubmitCompositorFrameToPresentationCompositorFrame +// PipelineReporter -> SubmitCompositorFrameToPresentationCompositorFrame or +// EventLatency -> SubmitCompositorFrameToPresentationCompositorFrame. constexpr const char* GetVizBreakdownName(VizBreakdown stage) { switch (stage) { case VizBreakdown::kSubmitToReceiveCompositorFrame: @@ -55,6 +61,14 @@ constexpr const char* GetVizBreakdownName(VizBreakdown stage) { return "Swap"; case VizBreakdown::kSwapEndToPresentationCompositorFrame: return "SwapEndToPresentationCompositorFrame"; + case VizBreakdown::kSwapStartToBufferAvailable: + return "SwapStartToBufferAvailable"; + case VizBreakdown::kBufferAvailableToBufferReady: + return "BufferAvailableToBufferReady"; + case VizBreakdown::kBufferReadyToLatch: + return "BufferReadyToLatch"; + case VizBreakdown::kLatchToSwapEnd: + return "LatchToSwapEnd"; case VizBreakdown::kBreakdownCount: NOTREACHED(); return ""; @@ -165,9 +179,9 @@ constexpr int kCompositorLatencyHistogramMax = 350000; constexpr int kCompositorLatencyHistogramBucketCount = 50; constexpr int kEventLatencyEventTypeCount = - static_cast<int>(ui::EventType::ET_LAST); + static_cast<int>(EventMetrics::EventType::kMaxValue) + 1; constexpr int kEventLatencyScrollTypeCount = - static_cast<int>(ui::ScrollInputType::kMaxValue) + 1; + static_cast<int>(EventMetrics::ScrollType::kMaxValue) + 1; constexpr int kMaxEventLatencyHistogramBaseIndex = kEventLatencyEventTypeCount * kEventLatencyScrollTypeCount; constexpr int kMaxEventLatencyHistogramIndex = @@ -203,37 +217,81 @@ std::string GetCompositorLatencyHistogramName( std::string GetEventLatencyHistogramBaseName( const EventMetrics& event_metrics) { - const bool is_scroll = event_metrics.scroll_input_type().has_value(); + const bool is_scroll = event_metrics.scroll_type().has_value(); return base::StrCat( {"EventLatency.", event_metrics.GetTypeName(), is_scroll ? "." : nullptr, is_scroll ? event_metrics.GetScrollTypeName() : nullptr}); } +base::TimeTicks ComputeSafeDeadlineForFrame(const viz::BeginFrameArgs& args) { + return args.frame_time + (args.interval * 1.5); +} + +void ReportOffsetBetweenDeadlineAndPresentationTime( + const viz::BeginFrameArgs& args, + base::TimeTicks presentation_time) { + const base::TimeTicks strict_deadline = args.frame_time + args.interval; + const base::TimeDelta offset = presentation_time - strict_deadline; + // |strict_deadline| and |presentation_time| should normally be pretty close. + // Measure how close they are. + UMA_HISTOGRAM_CUSTOM_TIMES( + "CompositorLatency.Diagnostic.PresentationTimeDeltaFromDeadline", offset, + base::TimeDelta::FromMilliseconds(1), + base::TimeDelta::FromMilliseconds(32), /*bucket_count=*/16); +} + +#define REPORT_VIZ_TRACE_EVENT(start_time, end_time, index, trace_func) \ + if (start_time <= end_time) { \ + const char* substage_name = \ + GetVizBreakdownName(static_cast<VizBreakdown>(index)); \ + trace_func(start_time, end_time, substage_name); \ + } + +#define REPORT_VIZ_BREAKDOWN_TRACES(trace_func) \ + size_t start_to_buffer_available = \ + static_cast<size_t>(VizBreakdown::kSwapStartToBufferAvailable); \ + bool has_ready_timings = !!viz_breakdown_list_[start_to_buffer_available]; \ + for (size_t i = 0; i < start_to_buffer_available; i++) { \ + if (!viz_breakdown_list_[i]) \ + break; \ + \ + if (i == static_cast<size_t>(VizBreakdown::kSwapStartToSwapEnd) && \ + has_ready_timings) { \ + size_t latch_to_swap_end = \ + static_cast<size_t>(VizBreakdown::kLatchToSwapEnd); \ + for (size_t j = start_to_buffer_available; j <= latch_to_swap_end; \ + j++) { \ + REPORT_VIZ_TRACE_EVENT(viz_breakdown_list_[j]->first, \ + viz_breakdown_list_[j]->second, j, trace_func); \ + } \ + } else { \ + REPORT_VIZ_TRACE_EVENT(viz_breakdown_list_[i]->first, \ + viz_breakdown_list_[i]->second, i, trace_func); \ + } \ + } + } // namespace CompositorFrameReporter::CompositorFrameReporter( const ActiveTrackers& active_trackers, - const viz::BeginFrameId& id, - const base::TimeTicks frame_deadline, + const viz::BeginFrameArgs& args, LatencyUkmReporter* latency_ukm_reporter, bool should_report_metrics) - : frame_id_(id), - should_report_metrics_(should_report_metrics), + : should_report_metrics_(should_report_metrics), + args_(args), active_trackers_(active_trackers), - latency_ukm_reporter_(latency_ukm_reporter), - frame_deadline_(frame_deadline) {} + latency_ukm_reporter_(latency_ukm_reporter) {} std::unique_ptr<CompositorFrameReporter> CompositorFrameReporter::CopyReporterAtBeginImplStage() const { if (stage_history_.empty() || stage_history_.front().stage_type != StageType::kBeginImplFrameToSendBeginMainFrame || - !did_finish_impl_frame()) { + (!did_finish_impl_frame() && !did_not_produce_frame_time_.has_value())) { return nullptr; } auto new_reporter = std::make_unique<CompositorFrameReporter>( - active_trackers_, frame_id_, frame_deadline_, latency_ukm_reporter_, - should_report_metrics_); + active_trackers_, args_, latency_ukm_reporter_, should_report_metrics_); new_reporter->did_finish_impl_frame_ = did_finish_impl_frame_; new_reporter->impl_frame_finish_time_ = impl_frame_finish_time_; new_reporter->main_frame_abort_time_ = main_frame_abort_time_; @@ -241,6 +299,7 @@ CompositorFrameReporter::CopyReporterAtBeginImplStage() const { StageType::kBeginImplFrameToSendBeginMainFrame; new_reporter->current_stage_.start_time = stage_history_.front().start_time; new_reporter->set_tick_clock(tick_clock_); + new_reporter->SetDroppedFrameCounter(dropped_frame_counter_); return new_reporter; } @@ -349,36 +408,33 @@ void CompositorFrameReporter::TerminateReporter() { PopulateVizBreakdownList(); DCHECK_EQ(current_stage_.start_time, base::TimeTicks()); - const char* termination_status_str = nullptr; switch (frame_termination_status_) { case FrameTerminationStatus::kPresentedFrame: EnableReportType(FrameReportType::kNonDroppedFrame); - termination_status_str = "presented_frame"; - if (frame_deadline_ < frame_termination_time_) + ReportOffsetBetweenDeadlineAndPresentationTime(args_, + frame_termination_time_); + if (ComputeSafeDeadlineForFrame(args_) < frame_termination_time_) EnableReportType(FrameReportType::kMissedDeadlineFrame); break; case FrameTerminationStatus::kDidNotPresentFrame: EnableReportType(FrameReportType::kDroppedFrame); - termination_status_str = "did_not_present_frame"; break; case FrameTerminationStatus::kReplacedByNewReporter: EnableReportType(FrameReportType::kDroppedFrame); - termination_status_str = "replaced_by_new_reporter_at_same_stage"; break; case FrameTerminationStatus::kDidNotProduceFrame: - termination_status_str = "did_not_produce_frame"; if (!frame_skip_reason_.has_value() || frame_skip_reason() != FrameSkippedReason::kNoDamage) { EnableReportType(FrameReportType::kDroppedFrame); - termination_status_str = "dropped_frame"; } break; case FrameTerminationStatus::kUnknown: - termination_status_str = "terminated_before_ending"; break; } - ReportAllTraceEvents(termination_status_str); + ReportCompositorLatencyTraceEvents(); + if (TestReportType(FrameReportType::kNonDroppedFrame)) + ReportEventLatencyTraceEvents(); // Only report compositor latency histograms if the frame was produced. if (should_report_metrics_ && report_types_.any()) { @@ -394,6 +450,17 @@ void CompositorFrameReporter::TerminateReporter() { if (TestReportType(FrameReportType::kNonDroppedFrame)) ReportEventLatencyHistograms(); } + + if (dropped_frame_counter_) { + if (TestReportType(FrameReportType::kDroppedFrame)) { + dropped_frame_counter_->AddDroppedFrame(); + } else { + if (has_partial_update_) + dropped_frame_counter_->AddPartialFrame(); + else + dropped_frame_counter_->AddGoodFrame(); + } + } } void CompositorFrameReporter::EndCurrentStage(base::TimeTicks end_time) { @@ -421,8 +488,8 @@ void CompositorFrameReporter::ReportCompositorLatencyHistograms() const { FrameReportType report_type = static_cast<FrameReportType>(type); UMA_HISTOGRAM_ENUMERATION("CompositorLatency.Type", report_type); if (latency_ukm_reporter_) { - latency_ukm_reporter_->ReportLatencyUkm(report_type, stage_history_, - active_trackers_, viz_breakdown_); + latency_ukm_reporter_->ReportCompositorLatencyUkm( + report_type, stage_history_, active_trackers_, viz_breakdown_); } for (size_t fst_type = 0; fst_type < active_trackers_.size(); ++fst_type) { if (!active_trackers_.test(fst_type)) { @@ -510,9 +577,11 @@ void CompositorFrameReporter::ReportCompositorLatencyVizBreakdowns( #endif break; } + const base::TimeTicks start_time = viz_breakdown_list_[i]->first; + const base::TimeTicks end_time = viz_breakdown_list_[i]->second; ReportCompositorLatencyHistogram(frame_sequence_tracker_type, kVizBreakdownInitialIndex + i, - *viz_breakdown_list_[i]); + end_time - start_time); } } @@ -561,8 +630,8 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const { GetEventLatencyHistogramBaseName(event_metrics); const int event_type_index = static_cast<int>(event_metrics.type()); const int scroll_type_index = - event_metrics.scroll_input_type() - ? static_cast<int>(*event_metrics.scroll_input_type()) + event_metrics.scroll_type() + ? static_cast<int>(*event_metrics.scroll_type()) : 0; const int histogram_base_index = event_type_index * kEventLatencyScrollTypeCount + scroll_type_index; @@ -570,8 +639,7 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const { // For scroll events, report total latency up to gpu-swap-end. This is // useful in comparing new EventLatency metrics with LatencyInfo-based // scroll event latency metrics. - if (event_metrics.scroll_input_type() && - !viz_breakdown_.swap_timings.is_null()) { + if (event_metrics.scroll_type() && !viz_breakdown_.swap_timings.is_null()) { const base::TimeDelta swap_end_latency = viz_breakdown_.swap_timings.swap_end - event_metrics.time_stamp(); const std::string swap_end_histogram_name = @@ -586,57 +654,51 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const { base::HistogramBase::kUmaTargetedHistogramFlag)); } - const auto trace_id = TRACE_ID_LOCAL(&event_metrics); - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1( - "cc,input", "EventLatency", trace_id, event_metrics.time_stamp(), - "event", event_metrics.GetTypeName()); - // It is possible for an event to arrive in the compositor in the middle of // a frame (e.g. the browser received the event *after* renderer received a // begin-impl, and the event reached the compositor before that frame // ended). To handle such cases, find the first stage that happens after the // event's arrival in the browser. - size_t index = 0; - for (; index < stage_history_.size(); ++index) { - const auto& stage = stage_history_[index]; - if (stage.start_time > event_metrics.time_stamp()) { - const char stage_type_name[] = "BrowserToRendererCompositor"; - - const base::TimeDelta latency = - stage.start_time - event_metrics.time_stamp(); - const std::string histogram_name = - base::StrCat({histogram_base_name, ".", stage_type_name}); - STATIC_HISTOGRAM_POINTER_GROUP( - histogram_name, histogram_base_index, - kMaxEventLatencyHistogramBaseIndex, - AddTimeMicrosecondsGranularity(latency), - base::Histogram::FactoryGet( - histogram_name, kEventLatencyHistogramMin, - kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount, - base::HistogramBase::kUmaTargetedHistogramFlag)); - - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "cc,input", stage_type_name, trace_id, event_metrics.time_stamp()); - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "cc,input", stage_type_name, trace_id, stage.start_time); - break; - } - } + auto stage_it = + std::find_if(stage_history_.begin(), stage_history_.end(), + [&event_metrics](const StageData& stage) { + return stage.start_time > event_metrics.time_stamp(); + }); + // TODO(crbug.com/1079116): Ideally, at least the start time of + // SubmitCompositorFrameToPresentationCompositorFrame stage should be + // greater than the event time stamp, but apparently, this is not always the + // case (see crbug.com/1093698). For now, skip to the next event in such + // cases. Hopefully, the work to reduce discrepancies between the new + // EventLatency and the old Event.Latency metrics would fix this issue. If + // not, we need to reconsider investigating this issue. + if (stage_it == stage_history_.end()) + continue; - for (; index < stage_history_.size(); ++index) { - const auto& stage = stage_history_[index]; + const base::TimeDelta b2r_latency = + stage_it->start_time - event_metrics.time_stamp(); + const std::string b2r_histogram_name = + histogram_base_name + ".BrowserToRendererCompositor"; + STATIC_HISTOGRAM_POINTER_GROUP( + b2r_histogram_name, histogram_base_index, + kMaxEventLatencyHistogramBaseIndex, + AddTimeMicrosecondsGranularity(b2r_latency), + base::Histogram::FactoryGet( + b2r_histogram_name, kEventLatencyHistogramMin, + kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount, + base::HistogramBase::kUmaTargetedHistogramFlag)); + for (; stage_it != stage_history_.end(); ++stage_it) { // Total latency is calculated since the event timestamp. const base::TimeTicks start_time = - stage.stage_type == StageType::kTotalLatency + stage_it->stage_type == StageType::kTotalLatency ? event_metrics.time_stamp() - : stage.start_time; - const base::TimeDelta latency = stage.end_time - start_time; - const int stage_type_index = static_cast<int>(stage.stage_type); + : stage_it->start_time; + const base::TimeDelta latency = stage_it->end_time - start_time; + const int stage_type_index = static_cast<int>(stage_it->stage_type); ReportEventLatencyHistogram(histogram_base_index, histogram_base_name, stage_type_index, latency); - switch (stage.stage_type) { + switch (stage_it->stage_type) { case StageType::kSendBeginMainFrameToCommit: ReportEventLatencyBlinkBreakdowns(histogram_base_index, histogram_base_name); @@ -648,18 +710,12 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const { default: break; } - - if (stage.stage_type != StageType::kTotalLatency) { - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "cc,input", GetStageName(stage_type_index), trace_id, - stage.start_time); - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "cc,input", GetStageName(stage_type_index), trace_id, - stage.end_time); - } } - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "cc,input", "EventLatency", trace_id, frame_termination_time_); + } + + if (latency_ukm_reporter_) { + latency_ukm_reporter_->ReportEventLatencyUkm( + events_metrics_, stage_history_, viz_breakdown_); } } @@ -685,9 +741,11 @@ void CompositorFrameReporter::ReportEventLatencyVizBreakdowns( #endif break; } + const base::TimeTicks start_time = viz_breakdown_list_[i]->first; + const base::TimeTicks end_time = viz_breakdown_list_[i]->second; ReportEventLatencyHistogram(histogram_base_index, histogram_base_name, kVizBreakdownInitialIndex + i, - *viz_breakdown_list_[i]); + end_time - start_time); } } @@ -710,32 +768,31 @@ void CompositorFrameReporter::ReportEventLatencyHistogram( base::HistogramBase::kUmaTargetedHistogramFlag)); } -void CompositorFrameReporter::ReportVizBreakdownTrace( - VizBreakdown substage, - const base::TimeTicks start_time, - const base::TimeTicks end_time) const { - // Do not report events with negative time span. - if (end_time < start_time) - return; - - const char* stage_name = GetVizBreakdownName(substage); - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "cc,benchmark", stage_name, TRACE_ID_LOCAL(this), start_time); - - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "cc,benchmark", stage_name, TRACE_ID_LOCAL(this), end_time); -} - -void CompositorFrameReporter::ReportAllTraceEvents( - const char* termination_status_str) const { +void CompositorFrameReporter::ReportCompositorLatencyTraceEvents() const { if (stage_history_.empty()) return; - const auto trace_id = TRACE_ID_LOCAL(this); - const auto& startstage = stage_history_.front(); - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1( - "cc,benchmark", "PipelineReporter", trace_id, startstage.start_time, - "frame_id", frame_id_.ToString()); + const auto trace_track = perfetto::Track(reinterpret_cast<uint64_t>(this)); + TRACE_EVENT_BEGIN( + "cc,benchmark", "PipelineReporter", trace_track, + stage_history_.front().start_time, [&](perfetto::EventContext context) { + using perfetto::protos::pbzero::ChromeFrameReporter; + bool frame_dropped = TestReportType(FrameReportType::kDroppedFrame); + ChromeFrameReporter::State state; + if (frame_dropped) { + state = ChromeFrameReporter::STATE_DROPPED; + } else if (frame_termination_status_ == + FrameTerminationStatus::kDidNotProduceFrame) { + state = ChromeFrameReporter::STATE_NO_UPDATE_DESIRED; + } else { + state = ChromeFrameReporter::STATE_PRESENTED_ALL; + } + auto* reporter = context.event()->set_chrome_frame_reporter(); + reporter->set_state(state); + reporter->set_frame_source(args_.frame_id.source_id); + reporter->set_frame_sequence(args_.frame_id.sequence_number); + // TODO(crbug.com/1086974): Set 'drop reason' if applicable. + }); // The trace-viewer cannot seem to handle a single child-event that has the // same start/end timestamps as the parent-event. So avoid adding the @@ -750,50 +807,89 @@ void CompositorFrameReporter::ReportAllTraceEvents( DCHECK_GE(stage.end_time, stage.start_time); if (stage.start_time == stage.end_time) continue; - const char* name = GetStageName(stage_type_index); + const char* stage_name = GetStageName(stage_type_index); + TRACE_EVENT_BEGIN("cc,benchmark", stage_name, trace_track, + stage.start_time); + if (stage.stage_type == + StageType::kSubmitCompositorFrameToPresentationCompositorFrame) { + REPORT_VIZ_BREAKDOWN_TRACES([&](base::TimeTicks start_time, + base::TimeTicks end_time, + const char* substage_name) { + TRACE_EVENT_BEGIN("cc,benchmark", substage_name, trace_track, + start_time); + TRACE_EVENT_END("cc,benchmark", trace_track, end_time); + }); + } + TRACE_EVENT_END("cc,benchmark", trace_track, stage.end_time); + } + } + + TRACE_EVENT_END("cc,benchmark", trace_track, frame_termination_time_); +} + +void CompositorFrameReporter::ReportEventLatencyTraceEvents() const { + for (const EventMetrics& event_metrics : events_metrics_) { + const auto trace_id = TRACE_ID_LOCAL(&event_metrics); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1( + "cc,input", "EventLatency", trace_id, event_metrics.time_stamp(), + "event", event_metrics.GetTypeName()); + + // Find the first stage that happens after the event's arrival in the + // browser. + auto stage_it = + std::find_if(stage_history_.begin(), stage_history_.end(), + [&event_metrics](const StageData& stage) { + return stage.start_time > event_metrics.time_stamp(); + }); + // TODO(crbug.com/1079116): Ideally, at least the start time of + // SubmitCompositorFrameToPresentationCompositorFrame stage should be + // greater than the event time stamp, but apparently, this is not always the + // case (see crbug.com/1093698). For now, skip to the next event in such + // cases. Hopefully, the work to reduce discrepancies between the new + // EventLatency and the old Event.Latency metrics would fix this issue. If + // not, we need to reconsider investigating this issue. + if (stage_it == stage_history_.end()) + continue; + + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( + "cc,input", "BrowserToRendererCompositor", trace_id, + event_metrics.time_stamp()); + TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( + "cc,input", "BrowserToRendererCompositor", trace_id, + stage_it->start_time); + + for (; stage_it != stage_history_.end(); ++stage_it) { + const int stage_type_index = static_cast<int>(stage_it->stage_type); + CHECK_LT(stage_type_index, static_cast<int>(StageType::kStageTypeCount)); + CHECK_GE(stage_type_index, 0); + if (stage_it->start_time >= frame_termination_time_) + break; + DCHECK_GE(stage_it->end_time, stage_it->start_time); + if (stage_it->start_time == stage_it->end_time) + continue; + const char* stage_name = GetStageName(stage_type_index); + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "cc,benchmark", name, trace_id, stage.start_time); + "cc,input", stage_name, trace_id, stage_it->start_time); - if (stage.stage_type == + if (stage_it->stage_type == StageType::kSubmitCompositorFrameToPresentationCompositorFrame) { - const struct { - VizBreakdown stage; - base::TimeTicks start_time; - base::TimeTicks end_time; - } sub_stages[] = { - {VizBreakdown::kSubmitToReceiveCompositorFrame, stage.start_time, - viz_breakdown_.received_compositor_frame_timestamp}, - {VizBreakdown::kReceivedCompositorFrameToStartDraw, - viz_breakdown_.received_compositor_frame_timestamp, - viz_breakdown_.draw_start_timestamp}, - {VizBreakdown::kStartDrawToSwapStart, - viz_breakdown_.draw_start_timestamp, - viz_breakdown_.swap_timings.swap_start}, - {VizBreakdown::kSwapStartToSwapEnd, - viz_breakdown_.swap_timings.swap_start, - viz_breakdown_.swap_timings.swap_end}, - {VizBreakdown::kSwapEndToPresentationCompositorFrame, - viz_breakdown_.swap_timings.swap_end, - viz_breakdown_.presentation_feedback.timestamp}}; - for (const auto& sub : sub_stages) { - if (sub.start_time.is_null() || sub.end_time.is_null()) - break; - ReportVizBreakdownTrace(sub.stage, sub.start_time, sub.end_time); - } + REPORT_VIZ_BREAKDOWN_TRACES([&](base::TimeTicks start_time, + base::TimeTicks end_time, + const char* substage_name) { + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( + "cc,input", substage_name, trace_id, start_time); + TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( + "cc,input", substage_name, trace_id, end_time); + }); } - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0("cc,benchmark", name, - trace_id, stage.end_time); + TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( + "cc,input", stage_name, trace_id, stage_it->end_time); } + TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( + "cc,input", "EventLatency", trace_id, frame_termination_time_); } - - const char* submission_status_str = - TestReportType(FrameReportType::kDroppedFrame) ? "dropped_frame" - : "non_dropped_frame"; - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP2( - "cc,benchmark", "PipelineReporter", trace_id, frame_termination_time_, - "termination_status", termination_status_str, - "compositor_frame_submission_status", submission_status_str); } void CompositorFrameReporter::PopulateBlinkBreakdownList() { @@ -839,29 +935,47 @@ void CompositorFrameReporter::PopulateVizBreakdownList() { } viz_breakdown_list_[static_cast<int>( VizBreakdown::kSubmitToReceiveCompositorFrame)] = - viz_breakdown_.received_compositor_frame_timestamp - viz_start_time_; + std::make_pair(viz_start_time_, + viz_breakdown_.received_compositor_frame_timestamp); if (viz_breakdown_.draw_start_timestamp.is_null()) return; viz_breakdown_list_[static_cast<int>( VizBreakdown::kReceivedCompositorFrameToStartDraw)] = - viz_breakdown_.draw_start_timestamp - - viz_breakdown_.received_compositor_frame_timestamp; + std::make_pair(viz_breakdown_.received_compositor_frame_timestamp, + viz_breakdown_.draw_start_timestamp); if (viz_breakdown_.swap_timings.is_null()) return; viz_breakdown_list_[static_cast<int>(VizBreakdown::kStartDrawToSwapStart)] = - viz_breakdown_.swap_timings.swap_start - - viz_breakdown_.draw_start_timestamp; + std::make_pair(viz_breakdown_.draw_start_timestamp, + viz_breakdown_.swap_timings.swap_start); viz_breakdown_list_[static_cast<int>(VizBreakdown::kSwapStartToSwapEnd)] = - viz_breakdown_.swap_timings.swap_end - - viz_breakdown_.swap_timings.swap_start; + std::make_pair(viz_breakdown_.swap_timings.swap_start, + viz_breakdown_.swap_timings.swap_end); viz_breakdown_list_[static_cast<int>( VizBreakdown::kSwapEndToPresentationCompositorFrame)] = - viz_breakdown_.presentation_feedback.timestamp - - viz_breakdown_.swap_timings.swap_end; + std::make_pair(viz_breakdown_.swap_timings.swap_end, + viz_breakdown_.presentation_feedback.timestamp); + + if (viz_breakdown_.presentation_feedback.ready_timestamp.is_null()) + return; + viz_breakdown_list_[static_cast<int>( + VizBreakdown::kSwapStartToBufferAvailable)] = + std::make_pair(viz_breakdown_.swap_timings.swap_start, + viz_breakdown_.presentation_feedback.available_timestamp); + viz_breakdown_list_[static_cast<int>( + VizBreakdown::kBufferAvailableToBufferReady)] = + std::make_pair(viz_breakdown_.presentation_feedback.available_timestamp, + viz_breakdown_.presentation_feedback.ready_timestamp); + viz_breakdown_list_[static_cast<int>(VizBreakdown::kBufferReadyToLatch)] = + std::make_pair(viz_breakdown_.presentation_feedback.ready_timestamp, + viz_breakdown_.presentation_feedback.latch_timestamp); + viz_breakdown_list_[static_cast<int>(VizBreakdown::kLatchToSwapEnd)] = + std::make_pair(viz_breakdown_.presentation_feedback.latch_timestamp, + viz_breakdown_.swap_timings.swap_end); } base::TimeDelta CompositorFrameReporter::SumOfStageHistory() const { diff --git a/chromium/cc/metrics/compositor_frame_reporter.h b/chromium/cc/metrics/compositor_frame_reporter.h index 9cae550ba76..2ff3b986489 100644 --- a/chromium/cc/metrics/compositor_frame_reporter.h +++ b/chromium/cc/metrics/compositor_frame_reporter.h @@ -7,6 +7,7 @@ #include <bitset> #include <memory> +#include <utility> #include <vector> #include "base/optional.h" @@ -26,6 +27,7 @@ struct FrameTimingDetails; } namespace cc { +class DroppedFrameCounter; class LatencyUkmReporter; // This is used for tracing and reporting the duration of pipeline stages within @@ -93,6 +95,13 @@ class CC_EXPORT CompositorFrameReporter { kStartDrawToSwapStart = 2, kSwapStartToSwapEnd = 3, kSwapEndToPresentationCompositorFrame = 4, + + // This is a breakdown of SwapStartToSwapEnd stage which is optionally + // recorded if querying these timestamps is supported by the platform. + kSwapStartToBufferAvailable = 5, + kBufferAvailableToBufferReady = 6, + kBufferReadyToLatch = 7, + kLatchToSwapEnd = 8, kBreakdownCount }; @@ -111,7 +120,7 @@ class CC_EXPORT CompositorFrameReporter { kBreakdownCount }; - struct StageData { + struct CC_EXPORT StageData { StageType stage_type; base::TimeTicks start_time; base::TimeTicks end_time; @@ -127,8 +136,7 @@ class CC_EXPORT CompositorFrameReporter { std::bitset<static_cast<size_t>(FrameSequenceTrackerType::kMaxType)>; CompositorFrameReporter(const ActiveTrackers& active_trackers, - const viz::BeginFrameId& id, - const base::TimeTicks frame_deadline, + const viz::BeginFrameArgs& args, LatencyUkmReporter* latency_ukm_reporter, bool should_report_metrics); ~CompositorFrameReporter(); @@ -139,8 +147,6 @@ class CC_EXPORT CompositorFrameReporter { std::unique_ptr<CompositorFrameReporter> CopyReporterAtBeginImplStage() const; - const viz::BeginFrameId frame_id_; - // Note that the started stage may be reported to UMA. If the histogram is // intended to be reported then the histograms.xml file must be updated too. void StartStage(StageType stage_type, base::TimeTicks start_time); @@ -183,6 +189,13 @@ class CC_EXPORT CompositorFrameReporter { tick_clock_ = tick_clock; } + void SetDroppedFrameCounter(DroppedFrameCounter* counter) { + dropped_frame_counter_ = counter; + } + void SetHasPartialUpdate() { has_partial_update_ = true; } + + const viz::BeginFrameId& frame_id() const { return args_.frame_id; } + private: void TerminateReporter(); void EndCurrentStage(base::TimeTicks end_time); @@ -213,15 +226,8 @@ class CC_EXPORT CompositorFrameReporter { int stage_type_index, base::TimeDelta latency) const; - // Generate a trace event corresponding to a Viz breakdown under - // SubmitCompositorFrameToPresentationCompositorFrame stage in - // PipelineReporter. This function only generates trace events and does not - // report histograms. - void ReportVizBreakdownTrace(VizBreakdown substage, - const base::TimeTicks start_time, - const base::TimeTicks end_time) const; - - void ReportAllTraceEvents(const char* termination_status_str) const; + void ReportCompositorLatencyTraceEvents() const; + void ReportEventLatencyTraceEvents() const; void EnableReportType(FrameReportType report_type) { report_types_.set(static_cast<size_t>(report_type)); @@ -239,6 +245,7 @@ class CC_EXPORT CompositorFrameReporter { base::TimeTicks Now() const; const bool should_report_metrics_; + const viz::BeginFrameArgs args_; StageData current_stage_; @@ -249,7 +256,7 @@ class CC_EXPORT CompositorFrameReporter { viz::FrameTimingDetails viz_breakdown_; base::TimeTicks viz_start_time_; - base::Optional<base::TimeDelta> + base::Optional<std::pair<base::TimeTicks, base::TimeTicks>> viz_breakdown_list_[static_cast<int>(VizBreakdown::kBreakdownCount)]; // Stage data is recorded here. On destruction these stages will be reported @@ -277,7 +284,6 @@ class CC_EXPORT CompositorFrameReporter { // The time that work on Impl frame is finished. It's only valid if the // reporter is in a stage other than begin impl frame. base::TimeTicks impl_frame_finish_time_; - base::TimeTicks frame_deadline_; // The timestamp of when the frame was marked as not having produced a frame // (through a call to DidNotProduceFrame()). @@ -286,7 +292,11 @@ class CC_EXPORT CompositorFrameReporter { base::Optional<base::TimeTicks> main_frame_abort_time_; const base::TickClock* tick_clock_ = base::DefaultTickClock::GetInstance(); + + DroppedFrameCounter* dropped_frame_counter_ = nullptr; + bool has_partial_update_ = false; }; + } // namespace cc #endif // CC_METRICS_COMPOSITOR_FRAME_REPORTER_H_" diff --git a/chromium/cc/metrics/compositor_frame_reporter_unittest.cc b/chromium/cc/metrics/compositor_frame_reporter_unittest.cc index afd8830e3e3..414655412dd 100644 --- a/chromium/cc/metrics/compositor_frame_reporter_unittest.cc +++ b/chromium/cc/metrics/compositor_frame_reporter_unittest.cc @@ -30,8 +30,7 @@ class CompositorFrameReporterTest : public testing::Test { CompositorFrameReporterTest() : pipeline_reporter_(std::make_unique<CompositorFrameReporter>( CompositorFrameReporter::ActiveTrackers(), - viz::BeginFrameId(), - base::TimeTicks() + base::TimeDelta::FromMilliseconds(16), + viz::BeginFrameArgs(), nullptr, /*should_report_metrics=*/true)) { pipeline_reporter_->set_tick_clock(&test_tick_clock_); diff --git a/chromium/cc/metrics/compositor_frame_reporting_controller.cc b/chromium/cc/metrics/compositor_frame_reporting_controller.cc index cd0ae991606..b19d869c968 100644 --- a/chromium/cc/metrics/compositor_frame_reporting_controller.cc +++ b/chromium/cc/metrics/compositor_frame_reporting_controller.cc @@ -68,11 +68,12 @@ void CompositorFrameReportingController::WillBeginImplFrame( reporter->did_not_produce_frame_time()); } auto reporter = std::make_unique<CompositorFrameReporter>( - active_trackers_, args.frame_id, args.frame_time + (args.interval * 1.5), - latency_ukm_reporter_.get(), should_report_metrics_); + active_trackers_, args, latency_ukm_reporter_.get(), + should_report_metrics_); reporter->set_tick_clock(tick_clock_); reporter->StartStage(StageType::kBeginImplFrameToSendBeginMainFrame, begin_time); + reporter->SetDroppedFrameCounter(dropped_frame_counter_); reporters_[PipelineStage::kBeginImplFrame] = std::move(reporter); } @@ -83,7 +84,7 @@ void CompositorFrameReportingController::WillBeginMainFrame( // C++20 feature. DCHECK_NE(reporters_[PipelineStage::kBeginMainFrame].get(), reporters_[PipelineStage::kBeginImplFrame].get()); - DCHECK_EQ(reporters_[PipelineStage::kBeginImplFrame]->frame_id_, + DCHECK_EQ(reporters_[PipelineStage::kBeginImplFrame]->frame_id(), args.frame_id); reporters_[PipelineStage::kBeginImplFrame]->StartStage( StageType::kSendBeginMainFrameToCommit, Now()); @@ -94,11 +95,11 @@ void CompositorFrameReportingController::WillBeginMainFrame( // beginMain frame before next BeginImplFrame (Not reached the ImplFrame // deadline yet). So will start a new reporter at BeginMainFrame. auto reporter = std::make_unique<CompositorFrameReporter>( - active_trackers_, args.frame_id, - args.frame_time + (args.interval * 1.5), latency_ukm_reporter_.get(), + active_trackers_, args, latency_ukm_reporter_.get(), should_report_metrics_); reporter->set_tick_clock(tick_clock_); reporter->StartStage(StageType::kSendBeginMainFrameToCommit, Now()); + reporter->SetDroppedFrameCounter(dropped_frame_counter_); reporters_[PipelineStage::kBeginMainFrame] = std::move(reporter); } } @@ -107,7 +108,7 @@ void CompositorFrameReportingController::BeginMainFrameAborted( const viz::BeginFrameId& id) { auto& reporter = reporters_[PipelineStage::kBeginMainFrame]; DCHECK(reporter); - DCHECK_EQ(reporter->frame_id_, id); + DCHECK_EQ(reporter->frame_id(), id); reporter->OnAbortBeginMainFrame(Now()); } @@ -169,7 +170,7 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame( // |impl_reporter| is guaranteed to be set, and |main_reporter| will not be // set. if (is_activated_frame_new) { - DCHECK_EQ(reporters_[PipelineStage::kActivate]->frame_id_, + DCHECK_EQ(reporters_[PipelineStage::kActivate]->frame_id(), last_activated_frame_id); // The reporter in activate state can be submitted main_reporter = std::move(reporters_[PipelineStage::kActivate]); @@ -205,6 +206,7 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame( if (reporter) { reporter->StartStage(StageType::kEndActivateToSubmitCompositorFrame, reporter->impl_frame_finish_time()); + reporter->SetHasPartialUpdate(); impl_reporter = std::move(reporter); } } @@ -220,7 +222,7 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame( DCHECK(main_reporter); // If there are impl events, there must be a reporter with // |current_frame_id|. - DCHECK_EQ(main_reporter->frame_id_, current_frame_id); + DCHECK_EQ(main_reporter->frame_id(), current_frame_id); events_metrics.main_event_metrics.reserve( events_metrics.main_event_metrics.size() + events_metrics.impl_event_metrics.size()); @@ -255,7 +257,7 @@ void CompositorFrameReportingController::DidNotProduceFrame( const viz::BeginFrameId& id, FrameSkippedReason skip_reason) { for (auto& stage_reporter : reporters_) { - if (stage_reporter && stage_reporter->frame_id_ == id) { + if (stage_reporter && stage_reporter->frame_id() == id) { // The reporter will be flagged and terminated when replaced by another // reporter. The reporter is not terminated immediately here because it // can still end up producing a frame afterwards. For example, if the @@ -264,7 +266,20 @@ void CompositorFrameReportingController::DidNotProduceFrame( // BeginMain stage, but the main-thread can make updates, which can be // submitted with the next frame. stage_reporter->OnDidNotProduceFrame(skip_reason); - return; + break; + } + } + + // If the compositor has no updates, and the main-thread has not responded to + // the begin-main-frame yet, then it is essentially a dropped frame. To handle + // this case, keep the reporter for the main-thread, but recreate a reporter + // for the dropped-frame. + if (skip_reason == FrameSkippedReason::kWaitingOnMain) { + auto reporter = RestoreReporterAtBeginImpl(id); + if (reporter) { + reporter->OnDidNotProduceFrame(skip_reason); + reporter->TerminateFrame(FrameTerminationStatus::kDidNotProduceFrame, + Now()); } } } @@ -272,7 +287,7 @@ void CompositorFrameReportingController::DidNotProduceFrame( void CompositorFrameReportingController::OnFinishImplFrame( const viz::BeginFrameId& id) { for (auto& reporter : reporters_) { - if (reporter && reporter->frame_id_ == id) { + if (reporter && reporter->frame_id() == id) { reporter->OnFinishImplFrame(Now()); return; } @@ -288,8 +303,10 @@ void CompositorFrameReportingController::DidPresentCompositorFrame( break; auto termination_status = FrameTerminationStatus::kPresentedFrame; - if (submitted_frame->frame_token != frame_token) + if (submitted_frame->frame_token != frame_token || + details.presentation_feedback.failed()) { termination_status = FrameTerminationStatus::kDidNotPresentFrame; + } submitted_frame->reporter->SetVizBreakdown(details); submitted_frame->reporter->TerminateFrame( @@ -356,7 +373,7 @@ bool CompositorFrameReportingController::CanSubmitImplFrame( if (!reporters_[PipelineStage::kBeginImplFrame]) return false; auto& reporter = reporters_[PipelineStage::kBeginImplFrame]; - return (reporter->frame_id_ == id && reporter->did_finish_impl_frame()); + return (reporter->frame_id() == id && reporter->did_finish_impl_frame()); } bool CompositorFrameReportingController::CanSubmitMainFrame( @@ -364,7 +381,7 @@ bool CompositorFrameReportingController::CanSubmitMainFrame( if (!reporters_[PipelineStage::kBeginMainFrame]) return false; auto& reporter = reporters_[PipelineStage::kBeginMainFrame]; - return (reporter->frame_id_ == id && reporter->did_finish_impl_frame() && + return (reporter->frame_id() == id && reporter->did_finish_impl_frame() && reporter->did_abort_main_frame()); } @@ -373,15 +390,15 @@ CompositorFrameReportingController::RestoreReporterAtBeginImpl( const viz::BeginFrameId& id) { auto& main_reporter = reporters_[PipelineStage::kBeginMainFrame]; auto& commit_reporter = reporters_[PipelineStage::kCommit]; - if (main_reporter && main_reporter->frame_id_ == id) + if (main_reporter && main_reporter->frame_id() == id) return main_reporter->CopyReporterAtBeginImplStage(); - if (commit_reporter && commit_reporter->frame_id_ == id) + if (commit_reporter && commit_reporter->frame_id() == id) return commit_reporter->CopyReporterAtBeginImplStage(); return nullptr; } void CompositorFrameReportingController::SetUkmManager(UkmManager* manager) { - latency_ukm_reporter_->SetUkmManager(manager); + latency_ukm_reporter_->set_ukm_manager(manager); } } // namespace cc diff --git a/chromium/cc/metrics/compositor_frame_reporting_controller.h b/chromium/cc/metrics/compositor_frame_reporting_controller.h index fb6b219ce27..2659e92b59d 100644 --- a/chromium/cc/metrics/compositor_frame_reporting_controller.h +++ b/chromium/cc/metrics/compositor_frame_reporting_controller.h @@ -20,6 +20,7 @@ struct FrameTimingDetails; } namespace cc { +class DroppedFrameCounter; class UkmManager; struct BeginMainFrameMetrics; @@ -85,6 +86,10 @@ class CC_EXPORT CompositorFrameReportingController { std::unique_ptr<CompositorFrameReporter>* reporters() { return reporters_; } + void SetDroppedFrameCounter(DroppedFrameCounter* counter) { + dropped_frame_counter_ = counter; + } + protected: struct SubmittedCompositorFrame { uint32_t frame_token; @@ -98,6 +103,9 @@ class CC_EXPORT CompositorFrameReportingController { base::TimeTicks Now() const; bool HasReporterAt(PipelineStage stage) const; + bool next_activate_has_invalidation() const { + return next_activate_has_invalidation_; + } private: void AdvanceReporterStage(PipelineStage start, PipelineStage target); @@ -128,6 +136,8 @@ class CC_EXPORT CompositorFrameReportingController { base::circular_deque<SubmittedCompositorFrame> submitted_compositor_frames_; const base::TickClock* tick_clock_ = base::DefaultTickClock::GetInstance(); + + DroppedFrameCounter* dropped_frame_counter_ = nullptr; }; } // namespace cc diff --git a/chromium/cc/metrics/compositor_frame_reporting_controller_unittest.cc b/chromium/cc/metrics/compositor_frame_reporting_controller_unittest.cc index ca70577d732..68bab0a45c1 100644 --- a/chromium/cc/metrics/compositor_frame_reporting_controller_unittest.cc +++ b/chromium/cc/metrics/compositor_frame_reporting_controller_unittest.cc @@ -524,13 +524,13 @@ TEST_F(CompositorFrameReportingControllerTest, args_3.interval, 0}; reporting_controller_.DidPresentCompositorFrame(1, details); - // Frame for |args_2| was dropped waiting on the main-thread. + // Frames for |args_1| and |args_2| were dropped waiting on the main-thread. histogram_tester.ExpectBucketCount( "CompositorLatency.Type", - CompositorFrameReporter::FrameReportType::kDroppedFrame, 1); + CompositorFrameReporter::FrameReportType::kDroppedFrame, 2); - // Frames for |args_1| and |args_3| were presented, although |args_1| missed - // its deadline. + // Frames for |args_1| and |args_3| were presented with |args_3|, and |args_1| + // missed its deadline. histogram_tester.ExpectBucketCount( "CompositorLatency.Type", CompositorFrameReporter::FrameReportType::kNonDroppedFrame, 2); diff --git a/chromium/cc/metrics/compositor_timing_history.cc b/chromium/cc/metrics/compositor_timing_history.cc index d0cc7d44262..99873a0152f 100644 --- a/chromium/cc/metrics/compositor_timing_history.cc +++ b/chromium/cc/metrics/compositor_timing_history.cc @@ -46,10 +46,6 @@ class CompositorTimingHistory::UMAReporter { // crbug.com/758439: the following functions are used to report timing in // certain conditions targeting blink / compositor animations. // Only the renderer would get the meaningful data. - virtual void AddDrawIntervalWithCompositedAnimations( - base::TimeDelta duration) = 0; - virtual void AddDrawIntervalWithMainThreadAnimations( - base::TimeDelta duration) = 0; virtual void AddDrawIntervalWithCustomPropertyAnimations( base::TimeDelta duration) = 0; }; @@ -310,18 +306,6 @@ class RendererUMAReporter : public CompositorTimingHistory::UMAReporter { interval); } - void AddDrawIntervalWithCompositedAnimations( - base::TimeDelta interval) override { - UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations", interval); - } - - void AddDrawIntervalWithMainThreadAnimations( - base::TimeDelta interval) override { - UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED( - "Scheduling.Renderer.DrawIntervalWithMainThreadAnimations", interval); - } - void AddDrawIntervalWithCustomPropertyAnimations( base::TimeDelta interval) override { UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED( @@ -396,12 +380,6 @@ class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter { // browser rendering fps is not at 60. void AddDrawInterval(base::TimeDelta interval) override {} - void AddDrawIntervalWithCompositedAnimations( - base::TimeDelta interval) override {} - - void AddDrawIntervalWithMainThreadAnimations( - base::TimeDelta interval) override {} - void AddDrawIntervalWithCustomPropertyAnimations( base::TimeDelta interval) override {} @@ -456,10 +434,6 @@ class NullUMAReporter : public CompositorTimingHistory::UMAReporter { ~NullUMAReporter() override = default; void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {} void AddDrawInterval(base::TimeDelta interval) override {} - void AddDrawIntervalWithCompositedAnimations( - base::TimeDelta inverval) override {} - void AddDrawIntervalWithMainThreadAnimations( - base::TimeDelta inverval) override {} void AddDrawIntervalWithCustomPropertyAnimations( base::TimeDelta inverval) override {} void AddBeginImplFrameLatency(base::TimeDelta delta) override {} @@ -861,10 +835,6 @@ void CompositorTimingHistory::WillDraw() { } void CompositorTimingHistory::DidDraw(bool used_new_active_tree, - size_t composited_animations_count, - size_t main_thread_animations_count, - bool current_frame_had_raf, - bool next_frame_has_pending_raf, bool has_custom_property_animations) { DCHECK_NE(base::TimeTicks(), draw_start_time_); base::TimeTicks draw_end_time = Now(); @@ -898,42 +868,16 @@ void CompositorTimingHistory::DidDraw(bool used_new_active_tree, TRACE_ID_LOCAL(g_num_long_draw_intervals), draw_end_time); g_num_long_draw_intervals++; } - if (composited_animations_count > 0 && - previous_frame_had_composited_animations_) - uma_reporter_->AddDrawIntervalWithCompositedAnimations(draw_interval); if (has_custom_property_animations && previous_frame_had_custom_property_animations_) uma_reporter_->AddDrawIntervalWithCustomPropertyAnimations(draw_interval); } - previous_frame_had_composited_animations_ = composited_animations_count > 0; previous_frame_had_custom_property_animations_ = has_custom_property_animations; draw_end_time_prev_ = draw_end_time; - if (used_new_active_tree) { - bool current_main_frame_had_visual_update = - main_thread_animations_count > 0 || current_frame_had_raf; - bool previous_main_frame_had_visual_update = - previous_frame_had_main_thread_animations_ || previous_frame_had_raf_; - if (current_main_frame_had_visual_update && - previous_main_frame_had_visual_update) { - base::TimeDelta draw_interval = - draw_end_time - new_active_tree_draw_end_time_prev_; - uma_reporter_->AddDrawIntervalWithMainThreadAnimations(draw_interval); - } - previous_frame_had_main_thread_animations_ = - main_thread_animations_count > 0; - // It's possible that two consecutive main frames both run a rAF but are - // separated by idle time (for example: calling requestAnimationFrame from a - // setInterval function, with nothing else producing a main frame - // in-between). To avoid incorrectly counting those cases as long draw - // intervals, we only update previous_frame_had_raf_ if the current frame - // also already has a future raf scheduled. - previous_frame_had_raf_ = - current_frame_had_raf && next_frame_has_pending_raf; - + if (used_new_active_tree) new_active_tree_draw_end_time_prev_ = draw_end_time; - } draw_start_time_ = base::TimeTicks(); } diff --git a/chromium/cc/metrics/compositor_timing_history.h b/chromium/cc/metrics/compositor_timing_history.h index 1d265a8419a..a4ff2503787 100644 --- a/chromium/cc/metrics/compositor_timing_history.h +++ b/chromium/cc/metrics/compositor_timing_history.h @@ -91,10 +91,6 @@ class CC_EXPORT CompositorTimingHistory { void DidActivate(); void WillDraw(); void DidDraw(bool used_new_active_tree, - size_t composited_animations_count, - size_t main_thread_animations_count, - bool current_frame_had_raf, - bool next_frame_has_pending_raf, bool has_custom_property_animations); void DidSubmitCompositorFrame( uint32_t frame_token, @@ -140,7 +136,6 @@ class CC_EXPORT CompositorTimingHistory { bool compositor_drawing_continuously_; base::TimeTicks begin_main_frame_end_time_prev_; base::TimeTicks new_active_tree_draw_end_time_prev_; - base::TimeTicks new_active_tree_draw_end_time_prev_committing_continuously_; base::TimeTicks draw_end_time_prev_; // If you add any history here, please remember to reset it in @@ -179,10 +174,7 @@ class CC_EXPORT CompositorTimingHistory { CompositorFrameReportingController* compositor_frame_reporting_controller_; // Used only for reporting animation targeted UMA. - bool previous_frame_had_composited_animations_ = false; - bool previous_frame_had_main_thread_animations_ = false; bool previous_frame_had_custom_property_animations_ = false; - bool previous_frame_had_raf_ = false; TreePriority tree_priority_ = SAME_PRIORITY_FOR_BOTH_TREES; }; diff --git a/chromium/cc/metrics/compositor_timing_history_unittest.cc b/chromium/cc/metrics/compositor_timing_history_unittest.cc index b5b713355d2..82c35dcad08 100644 --- a/chromium/cc/metrics/compositor_timing_history_unittest.cc +++ b/chromium/cc/metrics/compositor_timing_history_unittest.cc @@ -4,7 +4,6 @@ #include "cc/metrics/compositor_timing_history.h" -#include "base/test/metrics/histogram_tester.h" #include "cc/debug/rendering_stats_instrumentation.h" #include "cc/test/fake_compositor_frame_reporting_controller.h" #include "testing/gtest/include/gtest/gtest.h" @@ -53,43 +52,6 @@ class CompositorTimingHistoryTest : public testing::Test { base::TimeTicks Now() { return now_; } - // TODO(xidachen): the composited_animations_count should just be 0. - void DrawMainFrame(int advance_ms, - int composited_animations_count, - int main_thread_animations_count, - bool current_frame_had_raf = false, - bool next_frame_has_pending_raf = false) { - timing_history_.WillBeginMainFrame(getFakeBeginFrameArg()); - timing_history_.BeginMainFrameStarted(Now()); - timing_history_.WillCommit(); - timing_history_.DidCommit(); - timing_history_.ReadyToActivate(); - timing_history_.WillActivate(); - timing_history_.DidActivate(); - timing_history_.WillDraw(); - AdvanceNowBy(base::TimeDelta::FromMicroseconds(advance_ms)); - timing_history_.DidDraw(true, composited_animations_count, - main_thread_animations_count, current_frame_had_raf, - next_frame_has_pending_raf, false); - } - - void DrawImplFrame(int advance_ms, - int composited_animations_count, - int main_thread_animations_count, - bool has_custom_property_animation) { - viz::BeginFrameArgs args_ = getFakeBeginFrameArg(); - timing_history_.WillBeginMainFrame(args_); - timing_history_.BeginMainFrameStarted(Now()); - timing_history_.BeginMainFrameAborted(args_.frame_id); - timing_history_.WillActivate(); - timing_history_.DidActivate(); - timing_history_.WillDraw(); - AdvanceNowBy(base::TimeDelta::FromMicroseconds(advance_ms)); - timing_history_.DidDraw(false, composited_animations_count, - main_thread_animations_count, false, false, - has_custom_property_animation); - } - protected: std::unique_ptr<RenderingStatsInstrumentation> rendering_stats_; std::unique_ptr<CompositorFrameReportingController> reporting_controller_; @@ -148,7 +110,7 @@ TEST_F(CompositorTimingHistoryTest, AllSequential_Commit) { AdvanceNowBy(one_second); timing_history_.WillDraw(); AdvanceNowBy(draw_duration); - timing_history_.DidDraw(true, 0, 0, false, false, false); + timing_history_.DidDraw(true, false); EXPECT_EQ(begin_main_frame_queue_duration, timing_history_.BeginMainFrameQueueDurationCriticalEstimate()); @@ -200,7 +162,7 @@ TEST_F(CompositorTimingHistoryTest, AllSequential_BeginMainFrameAborted) { AdvanceNowBy(one_second); timing_history_.WillDraw(); AdvanceNowBy(draw_duration); - timing_history_.DidDraw(false, 0, 0, false, false, false); + timing_history_.DidDraw(false, false); EXPECT_EQ(base::TimeDelta(), timing_history_.BeginMainFrameQueueDurationCriticalEstimate()); @@ -320,179 +282,5 @@ TEST_F(CompositorTimingHistoryTest, BeginMainFrames_NewCriticalSlower) { timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate()); } -void TestAnimationUMA(const base::HistogramTester& histogram_tester, - base::HistogramBase::Count composited_animation_frames, - base::HistogramBase::Count main_thread_animation_frames) { - histogram_tester.ExpectTotalCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", - composited_animation_frames); - histogram_tester.ExpectTotalCount( - "Scheduling.Renderer.DrawIntervalWithMainThreadAnimations2", - main_thread_animation_frames); -} - -TEST_F(CompositorTimingHistoryTest, AnimationNotReported) { - base::HistogramTester histogram_tester; - - // Initial frame has no main-thread animations or rAF. - DrawMainFrame(123, 0, 0); - TestAnimationUMA(histogram_tester, 0, 0); - - // The next frame has one composited and one main thread animation running, - // but as the previous frame had no animation we shouldn't report anything. - DrawMainFrame(456, 1, 1); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawMainFrame(123, 0, 0); - TestAnimationUMA(histogram_tester, 0, 0); - - // The next frame has just one main thread animation running, but again as the - // previous frame had no animation we shouldn't report anything. - DrawMainFrame(456, 0, 1); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawMainFrame(123, 0, 0); - TestAnimationUMA(histogram_tester, 0, 0); - - // The next frame has no main thread animations but did have a rAF callback. - // Again as the previous frame had no visual change we shouldn't report. - DrawMainFrame(123, 0, 0, true); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawMainFrame(123, 0, 0); - TestAnimationUMA(histogram_tester, 0, 0); - - // Finally, test the combination of both main thread animations and rAF - // callbacks being called. - DrawMainFrame(123, 1, 2, true); - TestAnimationUMA(histogram_tester, 0, 0); -} - -TEST_F(CompositorTimingHistoryTest, ConsecutiveFramesAnimationsReported) { - base::HistogramTester histogram_tester; - - DrawMainFrame(123, 1, 0); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawMainFrame(456, 1, 0); - TestAnimationUMA(histogram_tester, 1, 0); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 456, 1); - - DrawMainFrame(321, 0, 1); - TestAnimationUMA(histogram_tester, 1, 0); - - DrawMainFrame(654, 0, 1); - TestAnimationUMA(histogram_tester, 1, 1); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithMainThreadAnimations2", 654, 1); - - DrawMainFrame(123, 0, 1); - TestAnimationUMA(histogram_tester, 1, 2); - - DrawMainFrame(456, 0, 1); - TestAnimationUMA(histogram_tester, 1, 3); - - // Main thread and rAF animations are both considered to be part of the same - // animation type. - DrawMainFrame(789, 0, 0, true, true); - TestAnimationUMA(histogram_tester, 1, 4); - - DrawMainFrame(987, 0, 1, false); - TestAnimationUMA(histogram_tester, 1, 5); - - // However if there is no pending rAF for a frame, we don't count the one - // after it as being linked. - DrawMainFrame(789, 0, 0, true, false); - TestAnimationUMA(histogram_tester, 1, 6); - - DrawMainFrame(987, 0, 0, true, true); - TestAnimationUMA(histogram_tester, 1, 6); -} - -TEST_F(CompositorTimingHistoryTest, InterFrameAnimationsNotReported) { - base::HistogramTester histogram_tester; - - DrawMainFrame(123, 0, 1); - TestAnimationUMA(histogram_tester, 0, 0); - - // The previous frame had a main thread animation, where the current one is - // main thread compositable animation, we don't measure the timing from a - // different animation type. - DrawMainFrame(456, 0, 1); - TestAnimationUMA(histogram_tester, 0, 1); - - DrawMainFrame(321, 1, 0); - TestAnimationUMA(histogram_tester, 0, 1); - - DrawMainFrame(654, 0, 1); - TestAnimationUMA(histogram_tester, 0, 1); - - DrawMainFrame(123, 1, 0); - TestAnimationUMA(histogram_tester, 0, 1); -} - -TEST_F(CompositorTimingHistoryTest, AnimationsWithNewActiveTreeNotUsed) { - base::HistogramTester histogram_tester; - - DrawImplFrame(123, 1, 1, false); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawImplFrame(456, 1, 0, false); - TestAnimationUMA(histogram_tester, 1, 0); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 456, 1); - - DrawMainFrame(321, 0, 1); - TestAnimationUMA(histogram_tester, 1, 0); - - // This frame verifies that we record that there is a composited animation, - // so in the next frame when there is a composited animation, we report it. - DrawImplFrame(234, 1, 1, false); - TestAnimationUMA(histogram_tester, 1, 0); - - // Even though the previous frame had no main thread animation, we report it - // in this frame because the previous main frame had a main thread animation - // with the time between main frame draws. - DrawMainFrame(654, 1, 1); - TestAnimationUMA(histogram_tester, 2, 1); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 654, 1); - // The recorded time for this main thread animation should be the total time - // between the two new tree activations, which is 234 + 654 = 888. - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithMainThreadAnimations2", 888, 1); - - DrawImplFrame(123, 1, 0, false); - TestAnimationUMA(histogram_tester, 3, 1); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 123, 1); -} - -TEST_F(CompositorTimingHistoryTest, CustomPropertyAnimations) { - base::HistogramTester histogram_tester; - - DrawImplFrame(123, 1, 0, true); - TestAnimationUMA(histogram_tester, 0, 0); - - DrawImplFrame(456, 1, 0, true); - TestAnimationUMA(histogram_tester, 1, 0); - - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 456, 1); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCustomPropertyAnimations2", 456, 1); - - DrawImplFrame(1234, 1, 0, false); - DrawImplFrame(2345, 1, 0, true); - TestAnimationUMA(histogram_tester, 3, 0); - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCompositedAnimations2", 2345, 1); - // This impl frame does have custom property animation, but the previous impl - // frame doesn't, so we won't report it. - histogram_tester.ExpectBucketCount( - "Scheduling.Renderer.DrawIntervalWithCustomPropertyAnimations2", 2345, 0); -} - } // namespace } // namespace cc diff --git a/chromium/cc/metrics/dropped_frame_counter.cc b/chromium/cc/metrics/dropped_frame_counter.cc new file mode 100644 index 00000000000..56564a2415f --- /dev/null +++ b/chromium/cc/metrics/dropped_frame_counter.cc @@ -0,0 +1,45 @@ +// Copyright 2020 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/metrics/dropped_frame_counter.h" + +#include <stddef.h> + +#include <limits> + +#include "base/memory/ptr_util.h" +#include "base/metrics/histogram_macros.h" + +namespace cc { + +DroppedFrameCounter::DroppedFrameCounter() = default; + +uint32_t DroppedFrameCounter::GetAverageThroughput() const { + size_t good_frames = 0; + for (auto it = --end(); it; --it) { + if (**it == kFrameStateComplete) + ++good_frames; + } + double throughput = 100. * good_frames / ring_buffer_.BufferSize(); + return static_cast<uint32_t>(throughput); +} + +void DroppedFrameCounter::AddGoodFrame() { + ring_buffer_.SaveToBuffer(kFrameStateComplete); + ++total_frames_; +} + +void DroppedFrameCounter::AddPartialFrame() { + ring_buffer_.SaveToBuffer(kFrameStatePartial); + ++total_frames_; + ++total_partial_; +} + +void DroppedFrameCounter::AddDroppedFrame() { + ring_buffer_.SaveToBuffer(kFrameStateDropped); + ++total_frames_; + ++total_dropped_; +} + +} // namespace cc diff --git a/chromium/cc/metrics/dropped_frame_counter.h b/chromium/cc/metrics/dropped_frame_counter.h new file mode 100644 index 00000000000..4929295ddce --- /dev/null +++ b/chromium/cc/metrics/dropped_frame_counter.h @@ -0,0 +1,55 @@ +// Copyright 2020 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. + +#ifndef CC_METRICS_DROPPED_FRAME_COUNTER_H_ +#define CC_METRICS_DROPPED_FRAME_COUNTER_H_ + +#include <stddef.h> + +#include <memory> + +#include "base/containers/ring_buffer.h" +#include "base/time/time.h" + +namespace cc { + +// This class maintains a counter for produced/dropped frames, and can be used +// to estimate the recent throughput. +class DroppedFrameCounter { + public: + enum FrameState { + kFrameStateDropped, + kFrameStatePartial, + kFrameStateComplete + }; + DroppedFrameCounter(); + + DroppedFrameCounter(const DroppedFrameCounter&) = delete; + DroppedFrameCounter& operator=(const DroppedFrameCounter&) = delete; + + size_t frame_history_size() const { return ring_buffer_.BufferSize(); } + size_t total_frames() const { return total_frames_; } + size_t total_compositor_dropped() const { return total_dropped_; } + size_t total_main_dropped() const { return total_partial_; } + + uint32_t GetAverageThroughput() const; + + typedef base::RingBuffer<FrameState, 180> RingBufferType; + RingBufferType::Iterator begin() const { return ring_buffer_.Begin(); } + RingBufferType::Iterator end() const { return ring_buffer_.End(); } + + void AddGoodFrame(); + void AddPartialFrame(); + void AddDroppedFrame(); + + private: + RingBufferType ring_buffer_; + size_t total_frames_ = 0; + size_t total_partial_ = 0; + size_t total_dropped_ = 0; +}; + +} // namespace cc + +#endif // CC_METRICS_DROPPED_FRAME_COUNTER_H_ diff --git a/chromium/cc/metrics/event_metrics.cc b/chromium/cc/metrics/event_metrics.cc index 326eaee70a1..951cdfc2ceb 100644 --- a/chromium/cc/metrics/event_metrics.cc +++ b/chromium/cc/metrics/event_metrics.cc @@ -4,98 +4,130 @@ #include "cc/metrics/event_metrics.h" +#include <utility> + #include "base/check.h" #include "base/memory/ptr_util.h" #include "base/notreached.h" #include "base/stl_util.h" namespace cc { +namespace { + +constexpr struct { + EventMetrics::EventType metrics_event_type; + ui::EventType ui_event_type; + const char* name; +} kWhitelistedEvents[] = { +#define EVENT_TYPE(name, ui_type) \ + { EventMetrics::EventType::k##name, ui_type, #name } + EVENT_TYPE(MousePressed, ui::ET_MOUSE_PRESSED), + EVENT_TYPE(MouseReleased, ui::ET_MOUSE_RELEASED), + EVENT_TYPE(MouseWheel, ui::ET_MOUSEWHEEL), + EVENT_TYPE(KeyPressed, ui::ET_KEY_PRESSED), + EVENT_TYPE(KeyReleased, ui::ET_KEY_RELEASED), + EVENT_TYPE(TouchPressed, ui::ET_TOUCH_PRESSED), + EVENT_TYPE(TouchReleased, ui::ET_TOUCH_RELEASED), + EVENT_TYPE(TouchMoved, ui::ET_TOUCH_MOVED), + EVENT_TYPE(GestureScrollBegin, ui::ET_GESTURE_SCROLL_BEGIN), + EVENT_TYPE(GestureScrollUpdate, ui::ET_GESTURE_SCROLL_UPDATE), + EVENT_TYPE(GestureScrollEnd, ui::ET_GESTURE_SCROLL_END), + EVENT_TYPE(GestureDoubleTap, ui::ET_GESTURE_DOUBLE_TAP), + EVENT_TYPE(GestureLongPress, ui::ET_GESTURE_LONG_PRESS), + EVENT_TYPE(GestureLongTap, ui::ET_GESTURE_LONG_TAP), + EVENT_TYPE(GestureShowPress, ui::ET_GESTURE_SHOW_PRESS), + EVENT_TYPE(GestureTap, ui::ET_GESTURE_TAP), + EVENT_TYPE(GestureTapCancel, ui::ET_GESTURE_TAP_CANCEL), + EVENT_TYPE(GestureTapDown, ui::ET_GESTURE_TAP_DOWN), + EVENT_TYPE(GestureTapUnconfirmed, ui::ET_GESTURE_TAP_UNCONFIRMED), + EVENT_TYPE(GestureTwoFingerTap, ui::ET_GESTURE_TWO_FINGER_TAP), +#undef EVENT_TYPE +}; +static_assert(base::size(kWhitelistedEvents) == + static_cast<int>(EventMetrics::EventType::kMaxValue) + 1, + "EventMetrics::EventType has changed."); + +constexpr struct { + EventMetrics::ScrollType metrics_scroll_type; + ui::ScrollInputType ui_scroll_type; + const char* name; +} kScrollTypes[] = { +#define SCROLL_TYPE(name, ui_type) \ + { EventMetrics::ScrollType::k##name, ui_type, #name } + SCROLL_TYPE(Autoscroll, ui::ScrollInputType::kAutoscroll), + SCROLL_TYPE(Scrollbar, ui::ScrollInputType::kScrollbar), + SCROLL_TYPE(Touchscreen, ui::ScrollInputType::kTouchscreen), + SCROLL_TYPE(Wheel, ui::ScrollInputType::kWheel), +#undef SCROLL_TYPE +}; +static_assert(base::size(kScrollTypes) == + static_cast<int>(EventMetrics::ScrollType::kMaxValue) + 1, + "EventMetrics::ScrollType has changed."); + +base::Optional<EventMetrics::EventType> ToWhitelistedEventType( + ui::EventType ui_event_type) { + for (size_t i = 0; i < base::size(kWhitelistedEvents); i++) { + if (ui_event_type == kWhitelistedEvents[i].ui_event_type) { + EventMetrics::EventType metrics_event_type = + static_cast<EventMetrics::EventType>(i); + DCHECK_EQ(metrics_event_type, kWhitelistedEvents[i].metrics_event_type); + return metrics_event_type; + } + } + return base::nullopt; +} + +base::Optional<EventMetrics::ScrollType> ToScrollType( + const base::Optional<ui::ScrollInputType>& scroll_input_type) { + if (!scroll_input_type) + return base::nullopt; + + for (size_t i = 0; i < base::size(kScrollTypes); i++) { + if (*scroll_input_type == kScrollTypes[i].ui_scroll_type) { + EventMetrics::ScrollType metrics_scroll_type = + static_cast<EventMetrics::ScrollType>(i); + DCHECK_EQ(metrics_scroll_type, kScrollTypes[i].metrics_scroll_type); + return metrics_scroll_type; + } + } + NOTREACHED(); + return base::nullopt; +} + +} // namespace std::unique_ptr<EventMetrics> EventMetrics::Create( ui::EventType type, base::TimeTicks time_stamp, base::Optional<ui::ScrollInputType> scroll_input_type) { - switch (type) { - case ui::ET_MOUSE_PRESSED: - case ui::ET_MOUSE_RELEASED: - case ui::ET_MOUSEWHEEL: - case ui::ET_KEY_PRESSED: - case ui::ET_KEY_RELEASED: - case ui::ET_TOUCH_PRESSED: - case ui::ET_TOUCH_RELEASED: - case ui::ET_TOUCH_MOVED: - case ui::ET_GESTURE_SCROLL_BEGIN: - case ui::ET_GESTURE_SCROLL_UPDATE: - case ui::ET_GESTURE_SCROLL_END: - return base::WrapUnique( - new EventMetrics(type, time_stamp, scroll_input_type)); - default: - return nullptr; - } + base::Optional<EventType> whitelisted_type = ToWhitelistedEventType(type); + if (!whitelisted_type) + return nullptr; + return base::WrapUnique(new EventMetrics(*whitelisted_type, time_stamp, + ToScrollType(scroll_input_type))); } -EventMetrics::EventMetrics( - ui::EventType type, - base::TimeTicks time_stamp, - base::Optional<ui::ScrollInputType> scroll_input_type) - : type_(type), - time_stamp_(time_stamp), - scroll_input_type_(scroll_input_type) {} +EventMetrics::EventMetrics(EventType type, + base::TimeTicks time_stamp, + base::Optional<ScrollType> scroll_type) + : type_(type), time_stamp_(time_stamp), scroll_type_(scroll_type) {} EventMetrics::EventMetrics(const EventMetrics&) = default; EventMetrics& EventMetrics::operator=(const EventMetrics&) = default; const char* EventMetrics::GetTypeName() const { - switch (type_) { - case ui::ET_MOUSE_PRESSED: - return "MousePressed"; - case ui::ET_MOUSE_RELEASED: - return "MouseReleased"; - case ui::ET_MOUSEWHEEL: - return "MouseWheel"; - case ui::ET_KEY_PRESSED: - // TODO(crbug/1071645): Currently, all ET_KEY_PRESSED events are reported - // under EventLatency.KeyPressed histogram. This includes both key-down - // and key-char events. Consider reporting them separately. - return "KeyPressed"; - case ui::ET_KEY_RELEASED: - return "KeyReleased"; - case ui::ET_TOUCH_PRESSED: - return "TouchPressed"; - case ui::ET_TOUCH_RELEASED: - return "TouchReleased"; - case ui::ET_TOUCH_MOVED: - return "TouchMoved"; - case ui::ET_GESTURE_SCROLL_BEGIN: - return "GestureScrollBegin"; - case ui::ET_GESTURE_SCROLL_UPDATE: - return "GestureScrollUpdate"; - case ui::ET_GESTURE_SCROLL_END: - return "GestureScrollEnd"; - default: - NOTREACHED(); - return nullptr; - } + return kWhitelistedEvents[static_cast<int>(type_)].name; } const char* EventMetrics::GetScrollTypeName() const { - DCHECK(scroll_input_type_) << "Event is not a scroll event"; - - switch (*scroll_input_type_) { - case ui::ScrollInputType::kTouchscreen: - return "Touchscreen"; - case ui::ScrollInputType::kWheel: - return "Wheel"; - case ui::ScrollInputType::kAutoscroll: - return "Autoscroll"; - case ui::ScrollInputType::kScrollbar: - return "Scrollbar"; - } + DCHECK(scroll_type_) << "Event is not a scroll event."; + + return kScrollTypes[static_cast<int>(*scroll_type_)].name; } bool EventMetrics::operator==(const EventMetrics& other) const { - return std::tie(type_, time_stamp_, scroll_input_type_) == - std::tie(other.type_, other.time_stamp_, other.scroll_input_type_); + return std::tie(type_, time_stamp_, scroll_type_) == + std::tie(other.type_, other.time_stamp_, other.scroll_type_); } // EventMetricsSet diff --git a/chromium/cc/metrics/event_metrics.h b/chromium/cc/metrics/event_metrics.h index 8de2fc58be9..df37365b7ed 100644 --- a/chromium/cc/metrics/event_metrics.h +++ b/chromium/cc/metrics/event_metrics.h @@ -6,6 +6,7 @@ #define CC_METRICS_EVENT_METRICS_H_ #include <memory> +#include <vector> #include "base/optional.h" #include "base/time/time.h" @@ -19,6 +20,45 @@ namespace cc { // latency metrics. class CC_EXPORT EventMetrics { public: + // Whitelisted event types. This list should be in the same order as values of + // EventLatencyEventType enum from enums.xml file. + enum class EventType { + kMousePressed, + kMouseReleased, + kMouseWheel, + // TODO(crbug/1071645): Currently, all ET_KEY_PRESSED events are reported + // under EventLatency.KeyPressed histogram. This includes both key-down and + // key-char events. Consider reporting them separately. + kKeyPressed, + kKeyReleased, + kTouchPressed, + kTouchReleased, + kTouchMoved, + kGestureScrollBegin, + kGestureScrollUpdate, + kGestureScrollEnd, + kGestureDoubleTap, + kGestureLongPress, + kGestureLongTap, + kGestureShowPress, + kGestureTap, + kGestureTapCancel, + kGestureTapDown, + kGestureTapUnconfirmed, + kGestureTwoFingerTap, + kMaxValue = kGestureTwoFingerTap, + }; + + // Type of scroll events. This list should be in the same order as values of + // EventLatencyScrollInputType enum from enums.xml file. + enum class ScrollType { + kAutoscroll, + kScrollbar, + kTouchscreen, + kWheel, + kMaxValue = kWheel, + }; + // Returns a new instance if |type| is a whitelisted event type. Otherwise, // returns nullptr. static std::unique_ptr<EventMetrics> Create( @@ -29,36 +69,33 @@ class CC_EXPORT EventMetrics { EventMetrics(const EventMetrics&); EventMetrics& operator=(const EventMetrics&); - // Returns a string representing event type. Should only be called for - // whitelisted event types. - const char* GetTypeName() const; - - // Returns a string representing scroll input type. Should only be called for - // scroll events. - const char* GetScrollTypeName() const; + EventType type() const { return type_; } - ui::EventType type() const { return type_; } + // Returns a string representing event type. + const char* GetTypeName() const; base::TimeTicks time_stamp() const { return time_stamp_; } - const base::Optional<ui::ScrollInputType>& scroll_input_type() const { - return scroll_input_type_; - } + const base::Optional<ScrollType>& scroll_type() const { return scroll_type_; } + + // Returns a string representing input type for a scroll event. Should only be + // called for scroll events. + const char* GetScrollTypeName() const; // Used in tests to check expectations on EventMetrics objects. bool operator==(const EventMetrics& other) const; private: - EventMetrics(ui::EventType type, + EventMetrics(EventType type, base::TimeTicks time_stamp, - base::Optional<ui::ScrollInputType> scroll_input_type); + base::Optional<ScrollType> scroll_type); - ui::EventType type_; + EventType type_; base::TimeTicks time_stamp_; // Only available for scroll events and represents the type of input device // for the event. - base::Optional<ui::ScrollInputType> scroll_input_type_; + base::Optional<ScrollType> scroll_type_; }; // Struct storing event metrics from both main and impl threads. diff --git a/chromium/cc/metrics/frame_sequence_metrics.cc b/chromium/cc/metrics/frame_sequence_metrics.cc index 0cefe55fd51..5933096b855 100644 --- a/chromium/cc/metrics/frame_sequence_metrics.cc +++ b/chromium/cc/metrics/frame_sequence_metrics.cc @@ -4,6 +4,10 @@ #include "cc/metrics/frame_sequence_metrics.h" +#include <memory> +#include <string> +#include <utility> + #include "base/metrics/histogram.h" #include "base/metrics/histogram_macros.h" #include "base/strings/strcat.h" @@ -91,13 +95,20 @@ bool IsInteractionType(FrameSequenceTrackerType sequence_type) { FrameSequenceMetrics::FrameSequenceMetrics(FrameSequenceTrackerType type, ThroughputUkmReporter* ukm_reporter) : type_(type), throughput_ukm_reporter_(ukm_reporter) { - TRACE_EVENT_NESTABLE_ASYNC_BEGIN1( - "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(this), "name", - FrameSequenceTracker::GetFrameSequenceTrackerTypeName(type_)); } -FrameSequenceMetrics::~FrameSequenceMetrics() { +FrameSequenceMetrics::~FrameSequenceMetrics() = default; + +void FrameSequenceMetrics::ReportLeftoverData() { if (HasDataLeftForReporting()) { + // Do this before ReportMetrics() which clears the throughput data. + // TODO(xidachen): Find a way to make ThroughputUkmReporter to directly talk + // to LayerTreeHostClient, and submit throughput data. Instead of storing + // the values in ThroughputUkmReporter. + if (type_ == FrameSequenceTrackerType::kUniversal && + HasEnoughDataForReporting()) { + throughput_ukm_reporter_->ComputeUniversalThroughput(this); + } ReportMetrics(); } } @@ -136,6 +147,8 @@ FrameSequenceMetrics::ThreadType FrameSequenceMetrics::GetEffectiveThread() return ThreadType::kSlower; case FrameSequenceTrackerType::kCustom: + return ThreadType::kMain; + case FrameSequenceTrackerType::kMaxType: NOTREACHED(); } @@ -144,6 +157,8 @@ FrameSequenceMetrics::ThreadType FrameSequenceMetrics::GetEffectiveThread() void FrameSequenceMetrics::Merge( std::unique_ptr<FrameSequenceMetrics> metrics) { + // Merging custom trackers are not supported. + DCHECK_NE(type_, FrameSequenceTrackerType::kCustom); DCHECK_EQ(type_, metrics->type_); DCHECK_EQ(GetEffectiveThread(), metrics->GetEffectiveThread()); impl_throughput_.Merge(metrics->impl_throughput_); @@ -169,6 +184,16 @@ bool FrameSequenceMetrics::HasDataLeftForReporting() const { main_throughput_.frames_expected > 0; } +void FrameSequenceMetrics::AdoptTrace(FrameSequenceMetrics* adopt_from) { + DCHECK(!trace_data_.trace_id); + trace_data_.trace_id = adopt_from->trace_data_.trace_id; + adopt_from->trace_data_.trace_id = nullptr; +} + +void FrameSequenceMetrics::AdvanceTrace(base::TimeTicks timestamp) { + trace_data_.Advance(timestamp); +} + void FrameSequenceMetrics::ComputeAggregatedThroughput() { // Whenever we are expecting and producing main frames, we are expecting and // producing impl frames as well. As an example, if we expect one main frame @@ -183,10 +208,11 @@ void FrameSequenceMetrics::ComputeAggregatedThroughput() { void FrameSequenceMetrics::ReportMetrics() { DCHECK_LE(impl_throughput_.frames_produced, impl_throughput_.frames_expected); DCHECK_LE(main_throughput_.frames_produced, main_throughput_.frames_expected); - TRACE_EVENT_NESTABLE_ASYNC_END2( - "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(this), "args", - ThroughputData::ToTracedValue(impl_throughput_, main_throughput_), - "checkerboard", frames_checkerboarded_); + DCHECK_LE(aggregated_throughput_.frames_produced, + aggregated_throughput_.frames_expected); + + // Terminates |trace_data_| for all types of FrameSequenceTracker. + trace_data_.Terminate(); if (type_ == FrameSequenceTrackerType::kCustom) { DCHECK(!custom_reporter_.is_null()); @@ -199,8 +225,6 @@ void FrameSequenceMetrics::ReportMetrics() { return; } - ComputeAggregatedThroughput(); - // Report the throughput metrics. base::Optional<int> impl_throughput_percent = ThroughputData::ReportHistogram( this, ThreadType::kCompositor, @@ -220,7 +244,8 @@ void FrameSequenceMetrics::ReportMetrics() { this, ThreadType::kSlower, GetIndexForMetric(FrameSequenceMetrics::ThreadType::kSlower, type_), aggregated_throughput_); - if (aggregated_throughput_percent.has_value() && throughput_ukm_reporter_) { + if (aggregated_throughput_percent.has_value() && throughput_ukm_reporter_ && + type_ != FrameSequenceTrackerType::kUniversal) { throughput_ukm_reporter_->ReportThroughputUkm( aggregated_throughput_percent, impl_throughput_percent, main_throughput_percent, type_); @@ -312,9 +337,7 @@ base::Optional<int> FrameSequenceMetrics::ThroughputData::ReportHistogram( // Throughput means the percent of frames that was expected to show on the // screen but didn't. In other words, the lower the throughput is, the // smoother user experience. - const int percent = - std::ceil(100 * (data.frames_expected - data.frames_produced) / - static_cast<double>(data.frames_expected)); + const int percent = data.DroppedFramePercent(); const bool is_animation = ShouldReportForAnimation(sequence_type, thread_type); @@ -323,6 +346,11 @@ base::Optional<int> FrameSequenceMetrics::ThroughputData::ReportHistogram( ThroughputUkmReporter* const ukm_reporter = metrics->ukm_reporter(); if (is_animation) { + TRACE_EVENT_INSTANT2("cc,benchmark", "PercentDroppedFrames.AllAnimations", + TRACE_EVENT_SCOPE_THREAD, "frames_expected", + data.frames_expected, "frames_produced", + data.frames_produced); + UMA_HISTOGRAM_PERCENTAGE( "Graphics.Smoothness.PercentDroppedFrames.AllAnimations", percent); if (ukm_reporter) { @@ -332,6 +360,10 @@ base::Optional<int> FrameSequenceMetrics::ThroughputData::ReportHistogram( } if (is_interaction) { + TRACE_EVENT_INSTANT2("cc,benchmark", "PercentDroppedFrames.AllInteractions", + TRACE_EVENT_SCOPE_THREAD, "frames_expected", + data.frames_expected, "frames_produced", + data.frames_produced); UMA_HISTOGRAM_PERCENTAGE( "Graphics.Smoothness.PercentDroppedFrames.AllInteractions", percent); if (ukm_reporter) { @@ -341,6 +373,10 @@ base::Optional<int> FrameSequenceMetrics::ThroughputData::ReportHistogram( } if (is_animation || is_interaction) { + TRACE_EVENT_INSTANT2("cc,benchmark", "PercentDroppedFrames.AllSequences", + TRACE_EVENT_SCOPE_THREAD, "frames_expected", + data.frames_expected, "frames_produced", + data.frames_produced); UMA_HISTOGRAM_PERCENTAGE( "Graphics.Smoothness.PercentDroppedFrames.AllSequences", percent); if (ukm_reporter) { @@ -368,4 +404,62 @@ base::Optional<int> FrameSequenceMetrics::ThroughputData::ReportHistogram( return percent; } +std::unique_ptr<base::trace_event::TracedValue> +FrameSequenceMetrics::ThroughputData::ToTracedValue( + const ThroughputData& impl, + const ThroughputData& main, + ThreadType effective_thread) { + auto dict = std::make_unique<base::trace_event::TracedValue>(); + if (effective_thread == ThreadType::kMain) { + dict->SetInteger("main-frames-produced", main.frames_produced); + dict->SetInteger("main-frames-expected", main.frames_expected); + } else { + dict->SetInteger("impl-frames-produced", impl.frames_produced); + dict->SetInteger("impl-frames-expected", impl.frames_expected); + } + return dict; +} + +FrameSequenceMetrics::TraceData::TraceData(FrameSequenceMetrics* m) + : metrics(m) { + TRACE_EVENT_CATEGORY_GROUP_ENABLED("cc,benchmark", &enabled); +} + +FrameSequenceMetrics::TraceData::~TraceData() = default; + +void FrameSequenceMetrics::TraceData::Terminate() { + if (!enabled || !trace_id) + return; + TRACE_EVENT_NESTABLE_ASYNC_END2( + "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(trace_id), "args", + ThroughputData::ToTracedValue(metrics->impl_throughput(), + metrics->main_throughput(), + metrics->GetEffectiveThread()), + "checkerboard", metrics->frames_checkerboarded()); + trace_id = nullptr; +} + +void FrameSequenceMetrics::TraceData::Advance(base::TimeTicks new_timestamp) { + if (!enabled) + return; + if (!trace_id) { + trace_id = this; + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1( + "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(trace_id), + this->last_timestamp, "name", + FrameSequenceTracker::GetFrameSequenceTrackerTypeName(metrics->type())); + } + // Use different names, because otherwise the trace-viewer shows the slices in + // the same color, and that makes it difficult to tell the traces apart from + // each other. + const char* trace_names[] = {"Frame", "Frame ", "Frame "}; + TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( + "cc,benchmark", trace_names[++this->frame_count % 3], + TRACE_ID_LOCAL(trace_id), this->last_timestamp); + TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( + "cc,benchmark", trace_names[this->frame_count % 3], + TRACE_ID_LOCAL(trace_id), new_timestamp); + this->last_timestamp = new_timestamp; +} + } // namespace cc diff --git a/chromium/cc/metrics/frame_sequence_metrics.h b/chromium/cc/metrics/frame_sequence_metrics.h index 0417899c3a9..3a77fc57775 100644 --- a/chromium/cc/metrics/frame_sequence_metrics.h +++ b/chromium/cc/metrics/frame_sequence_metrics.h @@ -5,6 +5,8 @@ #ifndef CC_METRICS_FRAME_SEQUENCE_METRICS_H_ #define CC_METRICS_FRAME_SEQUENCE_METRICS_H_ +#include <memory> + #include "base/callback.h" #include "base/optional.h" #include "base/trace_event/traced_value.h" @@ -44,7 +46,8 @@ class CC_EXPORT FrameSequenceMetrics { struct ThroughputData { static std::unique_ptr<base::trace_event::TracedValue> ToTracedValue( const ThroughputData& impl, - const ThroughputData& main); + const ThroughputData& main, + ThreadType effective_thred); // Returns the throughput in percent, a return value of base::nullopt // indicates that no throughput metric is reported. @@ -62,6 +65,13 @@ class CC_EXPORT FrameSequenceMetrics { #endif } + int DroppedFramePercent() const { + if (frames_expected == 0) + return 0; + return std::ceil(100 * (frames_expected - frames_produced) / + static_cast<double>(frames_expected)); + } + // Tracks the number of frames that were expected to be shown during this // frame-sequence. uint32_t frames_expected = 0; @@ -113,10 +123,31 @@ class CC_EXPORT FrameSequenceMetrics { return throughput_ukm_reporter_; } + // Must be called before destructor. + void ReportLeftoverData(); + + void AdoptTrace(FrameSequenceMetrics* adopt_from); + void AdvanceTrace(base::TimeTicks timestamp); + private: void ComputeAggregatedThroughput(); + const FrameSequenceTrackerType type_; + // Tracks some data to generate useful trace events. + struct TraceData { + explicit TraceData(FrameSequenceMetrics* metrics); + ~TraceData(); + FrameSequenceMetrics* metrics; + base::TimeTicks last_timestamp = base::TimeTicks::Now(); + int frame_count = 0; + bool enabled = false; + void* trace_id = nullptr; + + void Advance(base::TimeTicks new_timestamp); + void Terminate(); + } trace_data_{this}; + // Pointer to the reporter owned by the FrameSequenceTrackerCollection. ThroughputUkmReporter* const throughput_ukm_reporter_; diff --git a/chromium/cc/metrics/frame_sequence_metrics_unittest.cc b/chromium/cc/metrics/frame_sequence_metrics_unittest.cc index ae43da19a24..c2a1f76babb 100644 --- a/chromium/cc/metrics/frame_sequence_metrics_unittest.cc +++ b/chromium/cc/metrics/frame_sequence_metrics_unittest.cc @@ -6,6 +6,9 @@ #include "base/macros.h" #include "base/test/metrics/histogram_tester.h" +#include "cc/metrics/throughput_ukm_reporter.h" +#include "cc/trees/ukm_manager.h" +#include "components/ukm/test_ukm_recorder.h" #include "testing/gmock/include/gmock/gmock.h" #include "testing/gtest/include/gtest/gtest.h" @@ -28,6 +31,7 @@ TEST(FrameSequenceMetricsTest, AggregatedThroughputClearedAfterReport) { nullptr); first.impl_throughput().frames_expected = 200u; first.impl_throughput().frames_produced = 190u; + first.aggregated_throughput().frames_expected = 170u; first.aggregated_throughput().frames_produced = 150u; first.ReportMetrics(); @@ -35,6 +39,28 @@ TEST(FrameSequenceMetricsTest, AggregatedThroughputClearedAfterReport) { EXPECT_EQ(first.aggregated_throughput().frames_produced, 0u); } +// Test that ThroughputUkmReporter::ReportThroughputUkm isn't called for the +// kUniversal tracker. +TEST(FrameSequenceMetricsTest, UniversalNotReportUkmAtRenderer) { + auto recorder = std::make_unique<ukm::TestUkmRecorder>(); + auto ukm_manager = std::make_unique<UkmManager>(std::move(recorder)); + ThroughputUkmReporter reporter(ukm_manager.get()); + auto metric = std::make_unique<FrameSequenceMetrics>( + FrameSequenceTrackerType::kUniversal, &reporter); + + metric->impl_throughput().frames_expected = 200u; + metric->impl_throughput().frames_produced = 190u; + metric->aggregated_throughput().frames_expected = 170u; + metric->aggregated_throughput().frames_produced = 150u; + metric->ReportMetrics(); + + // The corresponding |samples_to_next_event_| element is 0 if the + // ReportThroughputUkm isn't called. + EXPECT_EQ(reporter.GetSamplesToNextEventForTesting( + static_cast<int>(FrameSequenceTrackerType::kUniversal)), + 1u); +} + TEST(FrameSequenceMetricsTest, MergeMetrics) { // Create a metric with only a small number of frames. It shouldn't report any // metrics. diff --git a/chromium/cc/metrics/frame_sequence_tracker.cc b/chromium/cc/metrics/frame_sequence_tracker.cc index f1a1fd9b995..dec83686b65 100644 --- a/chromium/cc/metrics/frame_sequence_tracker.cc +++ b/chromium/cc/metrics/frame_sequence_tracker.cc @@ -4,7 +4,13 @@ #include "cc/metrics/frame_sequence_tracker.h" +#include <algorithm> +#include <memory> +#include <string> +#include <utility> + #include "base/bind.h" +#include "base/logging.h" #include "base/metrics/histogram.h" #include "base/metrics/histogram_macros.h" #include "base/trace_event/trace_event.h" @@ -27,6 +33,8 @@ namespace cc { +using ThreadType = FrameSequenceMetrics::ThreadType; + // In the |TRACKER_TRACE_STREAM|, we mod the numbers such as frame sequence // number, or frame token, such that the debug string is not too long. constexpr int kDebugStrMod = 1000; @@ -63,9 +71,9 @@ FrameSequenceTracker::FrameSequenceTracker( FrameSequenceTrackerType type, ThroughputUkmReporter* throughput_ukm_reporter) : custom_sequence_id_(-1), - metrics_(std::make_unique<FrameSequenceMetrics>(type, - throughput_ukm_reporter)), - trace_data_(metrics_.get()) { + metrics_( + std::make_unique<FrameSequenceMetrics>(type, + throughput_ukm_reporter)) { DCHECK_LT(type, FrameSequenceTrackerType::kMaxType); DCHECK(type != FrameSequenceTrackerType::kCustom); } @@ -76,13 +84,14 @@ FrameSequenceTracker::FrameSequenceTracker( : custom_sequence_id_(custom_sequence_id), metrics_(std::make_unique<FrameSequenceMetrics>( FrameSequenceTrackerType::kCustom, - /*ukm_reporter=*/nullptr)), - trace_data_(metrics_.get()) { + /*ukm_reporter=*/nullptr)) { DCHECK_GT(custom_sequence_id_, 0); metrics_->SetCustomReporter(std::move(custom_reporter)); } -FrameSequenceTracker::~FrameSequenceTracker() = default; +FrameSequenceTracker::~FrameSequenceTracker() { + CleanUp(); +} void FrameSequenceTracker::ScheduleTerminate() { // If the last frame has ended and there is no frame awaiting presentation, @@ -126,6 +135,8 @@ void FrameSequenceTracker::ReportBeginImplFrame( args.frame_id.sequence_number); impl_throughput().frames_expected += begin_impl_frame_data_.previous_sequence_delta; + aggregated_throughput().frames_expected += + begin_impl_frame_data_.previous_sequence_delta; #if DCHECK_IS_ON() ++impl_throughput().frames_received; #endif @@ -363,6 +374,8 @@ void FrameSequenceTracker::ReportFrameEnd( NOTREACHED() << TRACKER_DCHECK_MSG; #endif begin_impl_frame_data_.previous_sequence = 0; + if (!IsExpectingMainFrame()) + --aggregated_throughput().frames_expected; } // last_submitted_frame_ == 0 means the last impl frame has been presented. if (termination_status_ == TerminationStatus::kScheduledForTermination && @@ -423,15 +436,17 @@ void FrameSequenceTracker::ReportFramePresented( uint32_t impl_frames_produced = 0; uint32_t main_frames_produced = 0; - trace_data_.Advance(feedback.timestamp); - const bool was_presented = !feedback.timestamp.is_null(); + const bool was_presented = !feedback.failed(); if (was_presented && submitted_frame_since_last_presentation) { DCHECK_LT(impl_throughput().frames_produced, impl_throughput().frames_expected) << TRACKER_DCHECK_MSG; ++impl_throughput().frames_produced; ++impl_frames_produced; + if (metrics()->GetEffectiveThread() == ThreadType::kCompositor) { + metrics()->AdvanceTrace(feedback.timestamp); + } } if (was_presented) { @@ -448,6 +463,9 @@ void FrameSequenceTracker::ReportFramePresented( << TRACKER_DCHECK_MSG; ++main_throughput().frames_produced; ++main_frames_produced; + if (metrics()->GetEffectiveThread() == ThreadType::kMain) { + metrics()->AdvanceTrace(feedback.timestamp); + } } if (impl_frames_produced > 0) { @@ -647,16 +665,11 @@ bool FrameSequenceTracker::ShouldIgnoreSequence( return sequence_number != begin_impl_frame_data_.previous_sequence; } -std::unique_ptr<base::trace_event::TracedValue> -FrameSequenceMetrics::ThroughputData::ToTracedValue( - const ThroughputData& impl, - const ThroughputData& main) { - auto dict = std::make_unique<base::trace_event::TracedValue>(); - dict->SetInteger("impl-frames-produced", impl.frames_produced); - dict->SetInteger("impl-frames-expected", impl.frames_expected); - dict->SetInteger("main-frames-produced", main.frames_produced); - dict->SetInteger("main-frames-expected", main.frames_expected); - return dict; +bool FrameSequenceTracker::IsExpectingMainFrame() const { + bool last_main_not_processed = + begin_main_frame_data_.previous_sequence != 0 && + begin_main_frame_data_.previous_sequence != last_processed_main_sequence_; + return !main_frames_.empty() || last_main_not_processed; } bool FrameSequenceTracker::ShouldReportMetricsNow( @@ -675,22 +688,12 @@ std::unique_ptr<FrameSequenceMetrics> FrameSequenceTracker::TakeMetrics() { return std::move(metrics_); } +void FrameSequenceTracker::CleanUp() { + if (metrics_) + metrics_->ReportLeftoverData(); +} + FrameSequenceTracker::CheckerboardingData::CheckerboardingData() = default; FrameSequenceTracker::CheckerboardingData::~CheckerboardingData() = default; -FrameSequenceTracker::TraceData::TraceData(const void* id) : trace_id(id) {} -void FrameSequenceTracker::TraceData::Advance(base::TimeTicks new_timestamp) { - // Use different names, because otherwise the trace-viewer shows the slices in - // the same color, and that makes it difficult to tell the traces apart from - // each other. - const char* trace_names[] = {"Frame", "Frame ", "Frame "}; - TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0( - "cc,benchmark", trace_names[++this->frame_count % 3], - TRACE_ID_LOCAL(this->trace_id), this->last_timestamp); - TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0( - "cc,benchmark", trace_names[this->frame_count % 3], - TRACE_ID_LOCAL(this->trace_id), new_timestamp); - this->last_timestamp = new_timestamp; -} - } // namespace cc diff --git a/chromium/cc/metrics/frame_sequence_tracker.h b/chromium/cc/metrics/frame_sequence_tracker.h index 680b2a85ad9..86deb91b3bd 100644 --- a/chromium/cc/metrics/frame_sequence_tracker.h +++ b/chromium/cc/metrics/frame_sequence_tracker.h @@ -5,6 +5,9 @@ #ifndef CC_METRICS_FRAME_SEQUENCE_TRACKER_H_ #define CC_METRICS_FRAME_SEQUENCE_TRACKER_H_ +#include <memory> +#include <sstream> + #include "base/containers/circular_deque.h" #include "base/containers/flat_map.h" #include "base/containers/flat_set.h" @@ -101,6 +104,10 @@ class CC_EXPORT FrameSequenceTracker { std::unique_ptr<FrameSequenceMetrics> TakeMetrics(); + // Called by the destructor of FrameSequenceTrackerCollection, asking its + // |metrics_| to report. + void CleanUp(); + private: friend class FrameSequenceTrackerCollection; friend class FrameSequenceTrackerTest; @@ -158,6 +165,8 @@ class CC_EXPORT FrameSequenceTracker { bool ShouldIgnoreSequence(uint64_t sequence_number) const; + bool IsExpectingMainFrame() const; + const int custom_sequence_id_; TerminationStatus termination_status_ = TerminationStatus::kActive; @@ -247,16 +256,6 @@ class CC_EXPORT FrameSequenceTracker { // TODO(xidachen): remove this one. uint64_t current_begin_main_sequence_ = 0; - // Tracks some data to generate useful trace events. - struct TraceData { - explicit TraceData(const void* trace_id); - const void* trace_id; - base::TimeTicks last_timestamp = base::TimeTicks::Now(); - int frame_count = 0; - - void Advance(base::TimeTicks new_timestamp); - } trace_data_; - // True when an impl-impl is not ended. A tracker is ready for termination // only when the last impl-frame is ended (ReportFrameEnd). bool is_inside_frame_ = false; diff --git a/chromium/cc/metrics/frame_sequence_tracker_collection.cc b/chromium/cc/metrics/frame_sequence_tracker_collection.cc index 8dd78ca0ccd..1efd3a37159 100644 --- a/chromium/cc/metrics/frame_sequence_tracker_collection.cc +++ b/chromium/cc/metrics/frame_sequence_tracker_collection.cc @@ -11,6 +11,18 @@ namespace cc { +namespace { + +using ThreadType = FrameSequenceMetrics::ThreadType; + +bool IsScrollType(FrameSequenceTrackerType type) { + return type == FrameSequenceTrackerType::kTouchScroll || + type == FrameSequenceTrackerType::kWheelScroll || + type == FrameSequenceTrackerType::kScrollbarScroll; +} + +} // namespace + FrameSequenceTrackerCollection::FrameSequenceTrackerCollection( bool is_single_threaded, CompositorFrameReportingController* compositor_frame_reporting_controller) @@ -19,42 +31,86 @@ FrameSequenceTrackerCollection::FrameSequenceTrackerCollection( compositor_frame_reporting_controller) {} FrameSequenceTrackerCollection::~FrameSequenceTrackerCollection() { + CleanUp(); frame_trackers_.clear(); removal_trackers_.clear(); } -FrameSequenceMetrics* FrameSequenceTrackerCollection::StartSequence( - FrameSequenceTrackerType type) { +FrameSequenceTracker* FrameSequenceTrackerCollection::StartSequenceInternal( + FrameSequenceTrackerType type, + FrameSequenceMetrics::ThreadType scrolling_thread) { DCHECK_NE(FrameSequenceTrackerType::kCustom, type); - if (is_single_threaded_) return nullptr; - if (frame_trackers_.contains(type)) - return frame_trackers_[type]->metrics(); + auto key = std::make_pair(type, scrolling_thread); + if (frame_trackers_.contains(key)) + return frame_trackers_[key].get(); + auto tracker = base::WrapUnique( new FrameSequenceTracker(type, throughput_ukm_reporter_.get())); - frame_trackers_[type] = std::move(tracker); + frame_trackers_[key] = std::move(tracker); if (compositor_frame_reporting_controller_) compositor_frame_reporting_controller_->AddActiveTracker(type); - return frame_trackers_[type]->metrics(); + + auto* metrics = frame_trackers_[key]->metrics(); + if (accumulated_metrics_.contains(key)) { + metrics->AdoptTrace(accumulated_metrics_[key].get()); + } + if (IsScrollType(type)) { + DCHECK_NE(scrolling_thread, ThreadType::kUnknown); + metrics->SetScrollingThread(scrolling_thread); + } + return frame_trackers_[key].get(); +} + +FrameSequenceTracker* FrameSequenceTrackerCollection::StartSequence( + FrameSequenceTrackerType type) { + DCHECK(!IsScrollType(type)); + return StartSequenceInternal(type, ThreadType::kUnknown); +} + +FrameSequenceTracker* FrameSequenceTrackerCollection::StartScrollSequence( + FrameSequenceTrackerType type, + FrameSequenceMetrics::ThreadType scrolling_thread) { + DCHECK(IsScrollType(type)); + return StartSequenceInternal(type, scrolling_thread); +} + +void FrameSequenceTrackerCollection::CleanUp() { + for (auto& tracker : frame_trackers_) + tracker.second->CleanUp(); + for (auto& tracker : custom_frame_trackers_) + tracker.second->CleanUp(); + for (auto& tracker : removal_trackers_) + tracker->CleanUp(); + for (auto& metric : accumulated_metrics_) + metric.second->ReportLeftoverData(); + throughput_ukm_reporter_ = nullptr; } void FrameSequenceTrackerCollection::StopSequence( FrameSequenceTrackerType type) { DCHECK_NE(FrameSequenceTrackerType::kCustom, type); - if (!frame_trackers_.contains(type)) + auto key = std::make_pair(type, ThreadType::kUnknown); + if (IsScrollType(type)) { + key = std::make_pair(type, ThreadType::kCompositor); + if (!frame_trackers_.contains(key)) + key = std::make_pair(type, ThreadType::kMain); + } + + if (!frame_trackers_.contains(key)) return; std::unique_ptr<FrameSequenceTracker> tracker = - std::move(frame_trackers_[type]); + std::move(frame_trackers_[key]); if (compositor_frame_reporting_controller_) compositor_frame_reporting_controller_->RemoveActiveTracker( tracker->type()); - frame_trackers_.erase(type); + frame_trackers_.erase(key); tracker->ScheduleTerminate(); removal_trackers_.push_back(std::move(tracker)); DestroyTrackers(); @@ -193,10 +249,42 @@ void FrameSequenceTrackerCollection::NotifyFramePresented( tracker.second->ReportFramePresented(frame_token, feedback); for (auto& tracker : custom_frame_trackers_) tracker.second->ReportFramePresented(frame_token, feedback); - for (auto& tracker : removal_trackers_) tracker->ReportFramePresented(frame_token, feedback); + DestroyTrackers(); +} + +bool FrameSequenceTrackerCollection::HasThroughputData() const { + return throughput_ukm_reporter_ && + throughput_ukm_reporter_->HasThroughputData(); +} + +int FrameSequenceTrackerCollection::TakeLastAggregatedPercent() { + DCHECK(throughput_ukm_reporter_); + return throughput_ukm_reporter_->TakeLastAggregatedPercent(); +} + +int FrameSequenceTrackerCollection::TakeLastImplPercent() { + DCHECK(throughput_ukm_reporter_); + return throughput_ukm_reporter_->TakeLastImplPercent(); +} + +base::Optional<int> FrameSequenceTrackerCollection::TakeLastMainPercent() { + DCHECK(throughput_ukm_reporter_); + return throughput_ukm_reporter_->TakeLastMainPercent(); +} + +void FrameSequenceTrackerCollection::ComputeUniversalThroughputForTesting() { + DCHECK(throughput_ukm_reporter_); + const auto type = FrameSequenceTrackerType::kUniversal; + auto key = std::make_pair(type, ThreadType::kUnknown); + DCHECK(frame_trackers_.contains(key)); + throughput_ukm_reporter_->ComputeUniversalThroughput( + frame_trackers_[key]->metrics()); +} + +void FrameSequenceTrackerCollection::DestroyTrackers() { for (auto& tracker : removal_trackers_) { if (tracker->termination_status() == FrameSequenceTracker::TerminationStatus::kReadyForTermination) { @@ -209,9 +297,10 @@ void FrameSequenceTrackerCollection::NotifyFramePresented( // For kCustom typed trackers, |metrics| invokes AddCustomTrackerResult // on its destruction, which add its data to |custom_tracker_results_| // to be picked up by caller. - auto metrics = tracker->TakeMetrics(); - if (metrics->type() == FrameSequenceTrackerType::kCustom) + if (tracker->metrics() && + tracker->type() == FrameSequenceTrackerType::kCustom) continue; + auto metrics = tracker->TakeMetrics(); auto key = std::make_pair(metrics->type(), metrics->GetEffectiveThread()); if (accumulated_metrics_.contains(key)) { @@ -220,24 +309,17 @@ void FrameSequenceTrackerCollection::NotifyFramePresented( } if (metrics->HasEnoughDataForReporting()) { - if (metrics->type() == FrameSequenceTrackerType::kUniversal) { - uint32_t frames_expected = metrics->impl_throughput().frames_expected; - uint32_t frames_produced = - metrics->aggregated_throughput().frames_produced; - current_universal_throughput_ = std::floor( - 100 * frames_produced / static_cast<float>(frames_expected)); - } + // Do this before ReportMetrics() which clears the throughput data. + if (metrics->type() == FrameSequenceTrackerType::kUniversal) + throughput_ukm_reporter_->ComputeUniversalThroughput(metrics.get()); metrics->ReportMetrics(); } - if (metrics->HasDataLeftForReporting()) + if (metrics->HasDataLeftForReporting()) { accumulated_metrics_[key] = std::move(metrics); + } } } - DestroyTrackers(); -} - -void FrameSequenceTrackerCollection::DestroyTrackers() { base::EraseIf( removal_trackers_, [](const std::unique_ptr<FrameSequenceTracker>& tracker) { @@ -248,28 +330,40 @@ void FrameSequenceTrackerCollection::DestroyTrackers() { void FrameSequenceTrackerCollection::RecreateTrackers( const viz::BeginFrameArgs& args) { - std::vector<FrameSequenceTrackerType> recreate_trackers; + std::vector<std::pair<FrameSequenceTrackerType, ThreadType>> + recreate_trackers; for (const auto& tracker : frame_trackers_) { if (tracker.second->ShouldReportMetricsNow(args)) recreate_trackers.push_back(tracker.first); } - for (const auto& tracker_type : recreate_trackers) { + for (const auto& key : recreate_trackers) { + DCHECK(frame_trackers_[key]); + auto tracker_type = key.first; + ThreadType thread_type = key.second; + // StopSequence put the tracker in the |removal_trackers_|, which will // report its throughput data when its frame is presented. StopSequence(tracker_type); + // The frame sequence is still active, so create a new tracker to keep // tracking this sequence. - StartSequence(tracker_type); + if (thread_type != FrameSequenceMetrics::ThreadType::kUnknown) { + DCHECK(IsScrollType(tracker_type)); + StartScrollSequence(tracker_type, thread_type); + } else { + StartSequence(tracker_type); + } } } ActiveFrameSequenceTrackers FrameSequenceTrackerCollection::FrameSequenceTrackerActiveTypes() { ActiveFrameSequenceTrackers encoded_types = 0; - for (const auto& tracker : frame_trackers_) { + for (const auto& key : frame_trackers_) { + auto thread_type = key.first.first; encoded_types |= static_cast<ActiveFrameSequenceTrackers>( - 1 << static_cast<unsigned>(tracker.first)); + 1 << static_cast<unsigned>(thread_type)); } return encoded_types; } @@ -281,13 +375,6 @@ FrameSequenceTrackerCollection::TakeCustomTrackerResults() { return results; } -FrameSequenceTracker* FrameSequenceTrackerCollection::GetTrackerForTesting( - FrameSequenceTrackerType type) { - if (!frame_trackers_.contains(type)) - return nullptr; - return frame_trackers_[type].get(); -} - FrameSequenceTracker* FrameSequenceTrackerCollection::GetRemovalTrackerForTesting( FrameSequenceTrackerType type) { diff --git a/chromium/cc/metrics/frame_sequence_tracker_collection.h b/chromium/cc/metrics/frame_sequence_tracker_collection.h index 9eaf1efb6b2..0fecfce7895 100644 --- a/chromium/cc/metrics/frame_sequence_tracker_collection.h +++ b/chromium/cc/metrics/frame_sequence_tracker_collection.h @@ -6,6 +6,8 @@ #define CC_METRICS_FRAME_SEQUENCE_TRACKER_COLLECTION_H_ #include <memory> +#include <utility> +#include <vector> #include "base/containers/flat_map.h" #include "base/optional.h" @@ -47,8 +49,12 @@ class CC_EXPORT FrameSequenceTrackerCollection { FrameSequenceTrackerCollection& operator=( const FrameSequenceTrackerCollection&) = delete; - // Creates a tracker for the specified sequence-type. - FrameSequenceMetrics* StartSequence(FrameSequenceTrackerType type); + // Creates a new tracker for the specified sequence-type if one doesn't + // already exist. Returns the associated FrameSequenceTracker instance. + FrameSequenceTracker* StartSequence(FrameSequenceTrackerType type); + FrameSequenceTracker* StartScrollSequence( + FrameSequenceTrackerType type, + FrameSequenceMetrics::ThreadType scrolling_thread); // Schedules |tracker| for destruction. This is preferred instead of outright // desrtruction of the tracker, since this ensures that the actual tracker @@ -103,23 +109,35 @@ class CC_EXPORT FrameSequenceTrackerCollection { // Reports the accumulated kCustom tracker results and clears it. CustomTrackerResults TakeCustomTrackerResults(); - FrameSequenceTracker* GetTrackerForTesting(FrameSequenceTrackerType type); FrameSequenceTracker* GetRemovalTrackerForTesting( FrameSequenceTrackerType type); void SetUkmManager(UkmManager* manager); - base::Optional<int> current_universal_throughput() { - return current_universal_throughput_; - } + // These methods directly calls corresponding APIs in ThroughputUkmReporter, + // please refer to the ThroughputUkmReporter for details. + bool HasThroughputData() const; + int TakeLastAggregatedPercent(); + int TakeLastImplPercent(); + base::Optional<int> TakeLastMainPercent(); + + void ComputeUniversalThroughputForTesting(); private: friend class FrameSequenceTrackerTest; + FrameSequenceTracker* StartSequenceInternal( + FrameSequenceTrackerType type, + FrameSequenceMetrics::ThreadType scrolling_thread); + void RecreateTrackers(const viz::BeginFrameArgs& args); // Destroy the trackers that are ready to be terminated. void DestroyTrackers(); + // Ask all trackers to report their metrics if there is any, must be the first + // thing in the destructor. + void CleanUp(); + // Adds collected metrics data for |custom_sequence_id| to be picked up via // TakeCustomTrackerResults() below. void AddCustomTrackerResult( @@ -127,9 +145,19 @@ class CC_EXPORT FrameSequenceTrackerCollection { FrameSequenceMetrics::ThroughputData throughput_data); const bool is_single_threaded_; + // The reporter takes throughput data and connect to UkmManager to report it. + // Note: this has to be before the frame_trackers_. The reason is that a + // FrameSequenceTracker owners a FrameSequenceMetrics, so the destructor of + // the former calls the destructor of the later. FrameSequenceMetrics's + // destructor calls its ReportMetrics() which requires + // |throughput_ukm_reporter_| to be alive. So putting it before + // |frame_trackers_| to ensure that it is destroyed after the tracker. + std::unique_ptr<ThroughputUkmReporter> throughput_ukm_reporter_; + // The callsite can use the type to manipulate the tracker. - base::flat_map<FrameSequenceTrackerType, - std::unique_ptr<FrameSequenceTracker>> + base::flat_map< + std::pair<FrameSequenceTrackerType, FrameSequenceMetrics::ThreadType>, + std::unique_ptr<FrameSequenceTracker>> frame_trackers_; // Custom trackers are keyed by a custom sequence id. @@ -141,14 +169,10 @@ class CC_EXPORT FrameSequenceTrackerCollection { CompositorFrameReportingController* const compositor_frame_reporting_controller_; - // The reporter takes throughput data and connect to UkmManager to report it. - std::unique_ptr<ThroughputUkmReporter> throughput_ukm_reporter_; - base::flat_map< std::pair<FrameSequenceTrackerType, FrameSequenceMetrics::ThreadType>, std::unique_ptr<FrameSequenceMetrics>> accumulated_metrics_; - base::Optional<int> current_universal_throughput_; }; } // namespace cc diff --git a/chromium/cc/metrics/frame_sequence_tracker_unittest.cc b/chromium/cc/metrics/frame_sequence_tracker_unittest.cc index 2a6b8cd2b82..963cf1045f4 100644 --- a/chromium/cc/metrics/frame_sequence_tracker_unittest.cc +++ b/chromium/cc/metrics/frame_sequence_tracker_unittest.cc @@ -8,6 +8,9 @@ #include "base/test/metrics/histogram_tester.h" #include "cc/metrics/compositor_frame_reporting_controller.h" #include "cc/metrics/frame_sequence_tracker_collection.h" +#include "cc/metrics/throughput_ukm_reporter.h" +#include "cc/trees/ukm_manager.h" +#include "components/ukm/test_ukm_recorder.h" #include "components/viz/common/frame_sinks/begin_frame_args.h" #include "testing/gmock/include/gmock/gmock.h" #include "testing/gtest/include/gtest/gtest.h" @@ -40,16 +43,16 @@ class FrameSequenceTrackerTest : public testing::Test { /*should_report_metrics=*/true)), collection_(/*is_single_threaded=*/false, compositor_frame_reporting_controller_.get()) { - collection_.StartSequence(FrameSequenceTrackerType::kTouchScroll); - tracker_ = collection_.GetTrackerForTesting( - FrameSequenceTrackerType::kTouchScroll); + tracker_ = collection_.StartScrollSequence( + FrameSequenceTrackerType::kTouchScroll, + FrameSequenceMetrics::ThreadType::kCompositor); } ~FrameSequenceTrackerTest() override = default; - void CreateNewTracker() { - collection_.StartSequence(FrameSequenceTrackerType::kTouchScroll); - tracker_ = collection_.GetTrackerForTesting( - FrameSequenceTrackerType::kTouchScroll); + void CreateNewTracker(FrameSequenceMetrics::ThreadType thread_type = + FrameSequenceMetrics::ThreadType::kCompositor) { + tracker_ = collection_.StartScrollSequence( + FrameSequenceTrackerType::kTouchScroll, thread_type); } viz::BeginFrameArgs CreateBeginFrameArgs( @@ -100,7 +103,15 @@ class FrameSequenceTrackerTest : public testing::Test { // Check whether a type of tracker exists in |frame_trackers_| or not. bool TrackerExists(FrameSequenceTrackerType type) const { - return collection_.frame_trackers_.contains(type); + auto key = std::make_pair(type, FrameSequenceMetrics::ThreadType::kUnknown); + if (type == FrameSequenceTrackerType::kTouchScroll || + type == FrameSequenceTrackerType::kWheelScroll || + type == FrameSequenceTrackerType::kScrollbarScroll) { + key = std::make_pair(type, FrameSequenceMetrics::ThreadType::kCompositor); + if (!collection_.frame_trackers_.contains(key)) + key = std::make_pair(type, FrameSequenceMetrics::ThreadType::kMain); + } + return collection_.frame_trackers_.contains(key); } bool RemovalTrackerExists(unsigned index, @@ -254,14 +265,29 @@ class FrameSequenceTrackerTest : public testing::Test { return tracker_->ignored_frame_tokens_; } + FrameSequenceMetrics::ThroughputData& ImplThroughput( + FrameSequenceTracker* tracker) const { + return tracker->impl_throughput(); + } + FrameSequenceMetrics::ThroughputData& ImplThroughput() const { return tracker_->impl_throughput(); } + FrameSequenceMetrics::ThroughputData& MainThroughput( + FrameSequenceTracker* tracker) const { + return tracker->main_throughput(); + } + FrameSequenceMetrics::ThroughputData& MainThroughput() const { return tracker_->main_throughput(); } + FrameSequenceMetrics::ThroughputData& AggregatedThroughput( + FrameSequenceTracker* tracker) const { + return tracker->aggregated_throughput(); + } + FrameSequenceMetrics::ThroughputData& AggregatedThroughput() const { return tracker_->aggregated_throughput(); } @@ -464,8 +490,6 @@ TEST_F(FrameSequenceTrackerTest, ReportMetrics) { 1u); histogram_tester.ExpectTotalCount( "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll", 0u); - histogram_tester.ExpectTotalCount( - "Graphics.Smoothness.PercentDroppedFrames.SlowerThread.TouchScroll", 1u); // Test that both are reported. ImplThroughput().frames_expected = 100u; @@ -478,8 +502,6 @@ TEST_F(FrameSequenceTrackerTest, ReportMetrics) { 2u); histogram_tester.ExpectTotalCount( "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll", 1u); - histogram_tester.ExpectTotalCount( - "Graphics.Smoothness.PercentDroppedFrames.SlowerThread.TouchScroll", 2u); // Test that none is reported. MainThroughput().frames_expected = 2u; @@ -492,8 +514,6 @@ TEST_F(FrameSequenceTrackerTest, ReportMetrics) { 2u); histogram_tester.ExpectTotalCount( "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll", 1u); - histogram_tester.ExpectTotalCount( - "Graphics.Smoothness.PercentDroppedFrames.SlowerThread.TouchScroll", 2u); // Test the case where compositor and main thread have the same throughput. ImplThroughput().frames_expected = 120u; @@ -506,8 +526,6 @@ TEST_F(FrameSequenceTrackerTest, ReportMetrics) { 3u); histogram_tester.ExpectTotalCount( "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll", 2u); - histogram_tester.ExpectTotalCount( - "Graphics.Smoothness.PercentDroppedFrames.SlowerThread.TouchScroll", 3u); } TEST_F(FrameSequenceTrackerTest, ReportMetricsAtFixedInterval) { @@ -638,9 +656,6 @@ TEST_F(FrameSequenceTrackerTest, BeginMainFrameSubmit) { } TEST_F(FrameSequenceTrackerTest, ScrollingThreadMetricCompositorThread) { - tracker_->metrics()->SetScrollingThread( - FrameSequenceMetrics::ThreadType::kCompositor); - // Start with a bunch of frames so that the metric does get reported at the // end of the test. ImplThroughput().frames_expected = 100u; @@ -659,8 +674,7 @@ TEST_F(FrameSequenceTrackerTest, ScrollingThreadMetricCompositorThread) { } TEST_F(FrameSequenceTrackerTest, ScrollingThreadMetricMainThread) { - tracker_->metrics()->SetScrollingThread( - FrameSequenceMetrics::ThreadType::kMain); + CreateNewTracker(FrameSequenceMetrics::ThreadType::kMain); // Start with a bunch of frames so that the metric does get reported at the // end of the test. @@ -1104,8 +1118,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame2) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1132,8 +1146,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame3) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1160,8 +1174,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame4) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1229,8 +1243,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame7) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1257,8 +1271,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame8) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1285,8 +1299,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame9) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1346,8 +1360,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame12) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1374,8 +1388,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame13) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1395,8 +1409,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame14) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1430,8 +1444,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame15) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1458,8 +1472,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame16) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1486,8 +1500,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame17) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1515,8 +1529,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame18) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1543,8 +1557,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame19) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1571,8 +1585,8 @@ TEST_F(FrameSequenceTrackerTest, TrackLastImplFrame20) { EXPECT_EQ(NumberOfRemovalTrackers(), 0u); std::string metric = "Graphics.Smoothness.FrameSequenceLength.TouchScroll"; - // Both impl and slower threads reports 101 frames expected. - EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 2); + // Impl thread reports 101 frames expected. + EXPECT_EQ(histogram_tester.GetBucketCount(metric, 101), 1); // The main thread reports 0 frames expected. EXPECT_EQ(histogram_tester.GetBucketCount(metric, 0), 1); metric = @@ -1851,7 +1865,8 @@ TEST_F(FrameSequenceTrackerTest, MainThreadPresentWithNullTimeStamp) { const char sequence[] = "b(1)B(0,1)E(1)s(1)S(1)e(1,1)"; GenerateSequence(sequence); collection_.NotifyFramePresented( - 1, {base::TimeTicks(), viz::BeginFrameArgs::DefaultInterval(), 0}); + 1, {base::TimeTicks(), viz::BeginFrameArgs::DefaultInterval(), + gfx::PresentationFeedback::kFailure}); EXPECT_EQ(MainThroughput().frames_expected, 1u); // No presentation, no main frame produced. EXPECT_EQ(MainThroughput().frames_produced, 0u); @@ -1869,6 +1884,29 @@ TEST_F(FrameSequenceTrackerTest, TrackerTypeEncoding) { EXPECT_EQ(active_encoded, 16); // 1 << 4 } +TEST_F(FrameSequenceTrackerTest, UniversalTrackerSubmitThroughput) { + auto recorder = std::make_unique<ukm::TestUkmRecorder>(); + auto ukm_manager = std::make_unique<UkmManager>(std::move(recorder)); + + collection_.ClearAll(); + collection_.SetUkmManager(ukm_manager.get()); + auto* tracker = + collection_.StartSequence(FrameSequenceTrackerType::kUniversal); + ImplThroughput(tracker).frames_expected = 200u; + ImplThroughput(tracker).frames_produced = 190u; + MainThroughput(tracker).frames_expected = 100u; + MainThroughput(tracker).frames_produced = 50u; + AggregatedThroughput(tracker).frames_expected = 200u; + AggregatedThroughput(tracker).frames_produced = 150u; + + collection_.ComputeUniversalThroughputForTesting(); + DCHECK(collection_.HasThroughputData()); + EXPECT_EQ(collection_.TakeLastAggregatedPercent(), 25); + EXPECT_EQ(collection_.TakeLastImplPercent(), 5); + EXPECT_EQ(collection_.TakeLastMainPercent().value(), 50); + EXPECT_FALSE(collection_.HasThroughputData()); +} + TEST_F(FrameSequenceTrackerTest, CustomTrackers) { // Start custom tracker 1. collection_.StartCustomSequence(1); @@ -1918,4 +1956,104 @@ TEST_F(FrameSequenceTrackerTest, CustomTrackers) { EXPECT_EQ(1u, results[3].frames_expected); } +TEST_F(FrameSequenceTrackerTest, MergeTrackers) { + // Generate two sequences of scrolls: first with only 1 frame, and then with + // 99 frames. Verify that the two scrolls are merged to report a single + // metric. + base::HistogramTester histogram_tester; + const char first_sequence[] = "b(1)s(1)e(1,0)P(1)"; + GenerateSequence(first_sequence); + EXPECT_EQ(ImplThroughput().frames_expected, 1u); + EXPECT_EQ(ImplThroughput().frames_produced, 1u); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + const char metric[] = + "Graphics.Smoothness.PercentDroppedFrames.CompositorThread.TouchScroll"; + histogram_tester.ExpectTotalCount(metric, 0u); + EXPECT_FALSE(TrackerExists(FrameSequenceTrackerType::kTouchScroll)); + + CreateNewTracker(); + const char second_sequence[] = "b(2)s(2)e(2,0)P(2)b(100)s(3)e(100,0)P(3)"; + GenerateSequence(second_sequence); + EXPECT_EQ(ImplThroughput().frames_expected, 99u); + EXPECT_EQ(ImplThroughput().frames_produced, 2u); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + EXPECT_FALSE(TrackerExists(FrameSequenceTrackerType::kTouchScroll)); + histogram_tester.ExpectTotalCount(metric, 1u); + EXPECT_THAT(histogram_tester.GetAllSamples(metric), + testing::ElementsAre(base::Bucket(97, 1))); +} + +TEST_F(FrameSequenceTrackerTest, MergeTrackersPresentAfterStopSequence) { + // Generate two sequences of scrolls: first with only 1 frame, and then with + // 99 frames. Verify that the two scrolls are merged to report a single + // metric. For the second sequence, the last frame is presented after the + // sequence ends. + base::HistogramTester histogram_tester; + const char first_sequence[] = "b(1)s(1)e(1,0)P(1)"; + GenerateSequence(first_sequence); + EXPECT_EQ(ImplThroughput().frames_expected, 1u); + EXPECT_EQ(ImplThroughput().frames_produced, 1u); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + const char metric[] = + "Graphics.Smoothness.PercentDroppedFrames.CompositorThread.TouchScroll"; + histogram_tester.ExpectTotalCount(metric, 0u); + EXPECT_FALSE(TrackerExists(FrameSequenceTrackerType::kTouchScroll)); + + CreateNewTracker(); + const char second_sequence[] = "b(2)s(2)e(2,0)P(2)b(100)s(3)e(100,0)"; + GenerateSequence(second_sequence); + EXPECT_EQ(ImplThroughput().frames_expected, 99u); + EXPECT_EQ(ImplThroughput().frames_produced, 1u); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + GenerateSequence("P(3)"); + histogram_tester.ExpectTotalCount(metric, 1u); + EXPECT_THAT(histogram_tester.GetAllSamples(metric), + testing::ElementsAre(base::Bucket(97, 1))); +} + +TEST_F(FrameSequenceTrackerTest, MergeTrackersScrollOnSameThread) { + // Do a short scroll on the compositor thread, then do another short scroll on + // the compositor thread. Make sure these are merged. + base::HistogramTester histogram_tester; + const char first_sequence[] = "b(1)s(1)e(1,0)P(1)b(80)s(2)e(80,0)P(2)"; + GenerateSequence(first_sequence); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + CreateNewTracker(FrameSequenceMetrics::ThreadType::kCompositor); + const char second_sequence[] = "b(81)s(3)e(81,0)P(3)b(101)s(4)e(101,0)P(4)"; + GenerateSequence(second_sequence); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + const char comp_metric[] = + "Graphics.Smoothness.PercentDroppedFrames.CompositorThread.TouchScroll"; + const char main_metric[] = + "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll"; + histogram_tester.ExpectTotalCount(comp_metric, 1u); + histogram_tester.ExpectTotalCount(main_metric, 0u); +} + +TEST_F(FrameSequenceTrackerTest, MergeTrackersScrollOnDifferentThreads) { + // Do a short scroll on the compositor thread, then do another short scroll on + // the main-thread. Make sure these are not merged. + base::HistogramTester histogram_tester; + const char compscroll_sequence[] = "b(1)s(1)e(1,0)P(1)b(80)s(2)e(80,0)P(2)"; + GenerateSequence(compscroll_sequence); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + CreateNewTracker(FrameSequenceMetrics::ThreadType::kMain); + const char mainscroll_sequence[] = + "b(81)s(3)e(81,0)P(3)b(101)s(4)e(101,0)P(4)"; + GenerateSequence(mainscroll_sequence); + collection_.StopSequence(FrameSequenceTrackerType::kTouchScroll); + + const char comp_metric[] = + "Graphics.Smoothness.PercentDroppedFrames.CompositorThread.TouchScroll"; + const char main_metric[] = + "Graphics.Smoothness.PercentDroppedFrames.MainThread.TouchScroll"; + histogram_tester.ExpectTotalCount(comp_metric, 0u); + histogram_tester.ExpectTotalCount(main_metric, 0u); +} + } // namespace cc diff --git a/chromium/cc/metrics/latency_ukm_reporter.cc b/chromium/cc/metrics/latency_ukm_reporter.cc index 072ccb31daf..5155ee6513c 100644 --- a/chromium/cc/metrics/latency_ukm_reporter.cc +++ b/chromium/cc/metrics/latency_ukm_reporter.cc @@ -4,57 +4,108 @@ #include "cc/metrics/latency_ukm_reporter.h" +#include <climits> +#include <memory> + #include "base/rand_util.h" #include "cc/trees/ukm_manager.h" namespace cc { -void LatencyUkmReporter::ReportLatencyUkm( +// We use a Poisson process with an exponential decay multiplier. The goal is to +// get many randomly distributed samples early during page load and initial +// interaction, then samples at an exponentially decreasing rate to effectively +// cap the number of samples. The particular parameters chosen here give roughly +// 5-10 samples in the first 100 frames, decaying to several hours between +// samples by the 40th sample. The multiplier value should be tuned to achieve a +// total sample count that avoids throttling by the UKM system. +class LatencyUkmReporter::SamplingController { + public: + SamplingController() = default; + ~SamplingController() = default; + + // When a new UKM event is issued, this function should be called (once and + // only once) by the client to determine whether that event should be recorded + // or ignored, according to the sampling parameters. The sampling state will + // be updated to be ready for the next UKM event. + bool ShouldRecordNextEvent() { + bool should_record = false; + if (!frames_to_next_event_) { + should_record = true; + frames_to_next_event_ = SampleFramesToNextEvent(); + } + DCHECK_GT(frames_to_next_event_, 0); + --frames_to_next_event_; + return should_record; + } + + private: + // The |kSampleRateMultiplier| and |kSampleDecayRate| have been set to meet + // UKM goals for data volume. + const double kSampleDecayRate = 1.0; + const double kSampleRateMultiplier = 2.0; + + int SampleFramesToNextEvent() { + // Sample from an exponential distribution to give a Poisson distribution + // of samples per time unit, then weigh it with an exponential multiplier + // to give a few samples in rapid succession (for frames early in the + // page's life) then exponentially fewer as the page lives longer. + // RandDouble() returns [0,1), but we need (0,1]. If RandDouble() is + // uniformly random, so is 1-RandDouble(), so use it to adjust the range. + // When RandDouble() returns 0.0, as it could, we will get a float_sample + // of 0, causing underflow. So rejection sample until we get a positive + // count. + double float_sample = 0.0; + do { + float_sample = -(kSampleRateMultiplier * + std::exp(samples_so_far_ * kSampleDecayRate) * + std::log(1.0 - base::RandDouble())); + } while (float_sample == 0.0); + // float_sample is positive, so we don't need to worry about underflow. + // After around 30 samples we will end up with a super high sample. That's + // OK because it just means we'll stop reporting metrics for that session, + // but we do need to be careful about overflow and NaN. + samples_so_far_++; + int integer_sample = + std::isnan(float_sample) + ? INT_MAX + : base::saturated_cast<int>(std::ceil(float_sample)); + return integer_sample; + } + + int samples_so_far_ = 0; + int frames_to_next_event_ = 0; +}; + +LatencyUkmReporter::LatencyUkmReporter() + : compositor_latency_sampling_controller_( + std::make_unique<SamplingController>()), + event_latency_sampling_controller_( + std::make_unique<SamplingController>()) {} + +LatencyUkmReporter::~LatencyUkmReporter() = default; + +void LatencyUkmReporter::ReportCompositorLatencyUkm( CompositorFrameReporter::FrameReportType report_type, const std::vector<CompositorFrameReporter::StageData>& stage_history, const CompositorFrameReporter::ActiveTrackers& active_trackers, const viz::FrameTimingDetails& viz_breakdown) { - if (!ukm_manager_) - return; - if (!frames_to_next_event_) { - ukm_manager_->RecordLatencyUKM(report_type, stage_history, active_trackers, - viz_breakdown); - frames_to_next_event_ += SampleFramesToNextEvent(); + if (ukm_manager_ && + compositor_latency_sampling_controller_->ShouldRecordNextEvent()) { + ukm_manager_->RecordCompositorLatencyUKM(report_type, stage_history, + active_trackers, viz_breakdown); } - DCHECK_GT(frames_to_next_event_, 0u); - --frames_to_next_event_; } -unsigned LatencyUkmReporter::SampleFramesToNextEvent() { - // Return the test interval if set - if (frames_to_next_event_for_test_) - return frames_to_next_event_for_test_; - - // Sample from an exponential distribution to give a poisson distribution - // of samples per time unit, then weigh it with an exponential multiplier to - // give a few samples in rapid succession (for frames early in the page's - // life) then exponentially fewer as the page lives longer. - // RandDouble() returns [0,1), but we need (0,1]. If RandDouble() is - // uniformly random, so is 1-RandDouble(), so use it to adjust the range. - // When RandDouble returns 0.0, as it could, we will get a float_sample of - // 0, causing underflow in UpdateEventTimeAndRecordIfNeeded. So rejection - // sample until we get a positive count. - double float_sample = 0; - do { - float_sample = -(sample_rate_multiplier_ * - std::exp(samples_so_far_ * sample_decay_rate_) * - std::log(1.0 - base::RandDouble())); - } while (float_sample == 0); - // float_sample is positive, so we don't need to worry about underflow. - // After around 30 samples we will end up with a super high - // sample. That's OK because it just means we'll stop reporting metrics - // for that session, but we do need to be careful about overflow and NaN. - samples_so_far_++; - unsigned unsigned_sample = - std::isnan(float_sample) - ? UINT_MAX - : base::saturated_cast<unsigned>(std::ceil(float_sample)); - return unsigned_sample; +void LatencyUkmReporter::ReportEventLatencyUkm( + const std::vector<EventMetrics>& events_metrics, + const std::vector<CompositorFrameReporter::StageData>& stage_history, + const viz::FrameTimingDetails& viz_breakdown) { + if (ukm_manager_ && + event_latency_sampling_controller_->ShouldRecordNextEvent()) { + ukm_manager_->RecordEventLatencyUKM(events_metrics, stage_history, + viz_breakdown); + } } } // namespace cc diff --git a/chromium/cc/metrics/latency_ukm_reporter.h b/chromium/cc/metrics/latency_ukm_reporter.h index 3ee27823a4b..e5b0a8ac273 100644 --- a/chromium/cc/metrics/latency_ukm_reporter.h +++ b/chromium/cc/metrics/latency_ukm_reporter.h @@ -5,9 +5,12 @@ #ifndef CC_METRICS_LATENCY_UKM_REPORTER_H_ #define CC_METRICS_LATENCY_UKM_REPORTER_H_ -#include "base/optional.h" +#include <memory> +#include <vector> + #include "cc/cc_export.h" #include "cc/metrics/compositor_frame_reporter.h" +#include "cc/metrics/event_metrics.h" #include "components/viz/common/frame_timing_details.h" namespace cc { @@ -17,25 +20,27 @@ class UkmManager; // talks to UkmManager to report it. class CC_EXPORT LatencyUkmReporter { public: - LatencyUkmReporter() = default; - ~LatencyUkmReporter() = default; + LatencyUkmReporter(); + ~LatencyUkmReporter(); + + LatencyUkmReporter(const LatencyUkmReporter&) = delete; + LatencyUkmReporter& operator=(const LatencyUkmReporter&) = delete; - void ReportLatencyUkm( + void ReportCompositorLatencyUkm( CompositorFrameReporter::FrameReportType report_type, const std::vector<CompositorFrameReporter::StageData>& stage_history, const CompositorFrameReporter::ActiveTrackers& active_trackers, const viz::FrameTimingDetails& viz_breakdown); - void SetUkmManager(UkmManager* manager) { ukm_manager_ = manager; } + void ReportEventLatencyUkm( + const std::vector<EventMetrics>& events_metrics, + const std::vector<CompositorFrameReporter::StageData>& stage_history, + const viz::FrameTimingDetails& viz_breakdown); - private: - unsigned SampleFramesToNextEvent(); + void set_ukm_manager(UkmManager* manager) { ukm_manager_ = manager; } - // To test event sampling. This and all future intervals will be the given - // frame count, until this is called again. - void FramesToNextEventForTest(unsigned num_frames) { - frames_to_next_event_for_test_ = num_frames; - } + private: + class SamplingController; // This is pointing to the LayerTreeHostImpl::ukm_manager_, which is // initialized right after the LayerTreeHostImpl is created. So when this @@ -44,23 +49,8 @@ class CC_EXPORT LatencyUkmReporter { // this pointer should never be null as long as LayerTreeHostImpl is alive. UkmManager* ukm_manager_ = nullptr; - // Sampling control. We use a Poisson process with an exponential decay - // multiplier. The goal is to get many randomly distributed samples early - // during page load and initial interaction, then samples at an exponentially - // decreasing rate to effectively cap the number of samples. The particular - // parameters chosen here give roughly 5-10 samples in the first 100 frames, - // decaying to several hours between samples by the 40th sample. The - // multiplier value should be tuned to achieve a total sample count that - // avoids throttling by the UKM system. - // The sample_rate_multiplier_ and sample_decay_rate_ have been set to meet - // UKM goals for data volume. - double sample_decay_rate_ = 1; - double sample_rate_multiplier_ = 2; - unsigned samples_so_far_ = 0; - unsigned frames_to_next_event_ = 0; - - // Test data, used for SampleFramesToNextEvent if present - unsigned frames_to_next_event_for_test_ = 0; + std::unique_ptr<SamplingController> compositor_latency_sampling_controller_; + std::unique_ptr<SamplingController> event_latency_sampling_controller_; }; } // namespace cc diff --git a/chromium/cc/metrics/throughput_ukm_reporter.cc b/chromium/cc/metrics/throughput_ukm_reporter.cc index 08369a64156..39f1a33f7ce 100644 --- a/chromium/cc/metrics/throughput_ukm_reporter.cc +++ b/chromium/cc/metrics/throughput_ukm_reporter.cc @@ -30,6 +30,11 @@ void ThroughputUkmReporter::ReportThroughputUkm( const base::Optional<int>& impl_throughput_percent, const base::Optional<int>& main_throughput_percent, FrameSequenceTrackerType type) { + // It is possible that when a tab shuts down, the ukm_manager_ owned by the + // LayerTreeHostImpl is cleared, and yet we try to report to UKM here. In this + // case, the |ukm_manager_| here is null. + if (!ukm_manager_) + return; if (samples_to_next_event_[static_cast<int>(type)] == 0) { // Sample every 100 events. Using the Universal tracker as an example // which reports UMA every 5s, then the system collects UKM once per @@ -65,4 +70,42 @@ void ThroughputUkmReporter::ReportAggregateThroughput( --samples_for_aggregated_report_; } +void ThroughputUkmReporter::ComputeUniversalThroughput( + FrameSequenceMetrics* metrics) { + last_impl_percent_ = metrics->impl_throughput().DroppedFramePercent(); + last_main_percent_ = metrics->main_throughput().DroppedFramePercent(); + last_aggregated_percent_ = + metrics->aggregated_throughput().DroppedFramePercent(); +} + +bool ThroughputUkmReporter::HasThroughputData() const { + return last_aggregated_percent_.has_value(); +} + +int ThroughputUkmReporter::TakeLastAggregatedPercent() { + int ret_value = last_aggregated_percent_.value(); + DCHECK(ret_value >= 0 && ret_value <= 100); + last_aggregated_percent_ = base::nullopt; + return ret_value; +} + +int ThroughputUkmReporter::TakeLastImplPercent() { + int ret_value = last_impl_percent_.value(); + DCHECK(ret_value >= 0 && ret_value <= 100); + last_impl_percent_ = base::nullopt; + return ret_value; +} + +base::Optional<int> ThroughputUkmReporter::TakeLastMainPercent() { + base::Optional<int> ret_value = last_main_percent_; + DCHECK(!ret_value || (ret_value.value() >= 0 && ret_value.value() <= 100)); + last_main_percent_ = base::nullopt; + return ret_value; +} + +uint32_t ThroughputUkmReporter::GetSamplesToNextEventForTesting(int index) { + DCHECK_LT(index, static_cast<int>(FrameSequenceTrackerType::kMaxType)); + return samples_to_next_event_[index]; +} + } // namespace cc diff --git a/chromium/cc/metrics/throughput_ukm_reporter.h b/chromium/cc/metrics/throughput_ukm_reporter.h index 441be89f88a..c92fdfe33b4 100644 --- a/chromium/cc/metrics/throughput_ukm_reporter.h +++ b/chromium/cc/metrics/throughput_ukm_reporter.h @@ -36,6 +36,23 @@ class CC_EXPORT ThroughputUkmReporter { void ReportAggregateThroughput(AggregationType aggregation_type, int throughput); + void ComputeUniversalThroughput(FrameSequenceMetrics* metrics); + + // Once the kUniversal tracker reported its throughput to UMA, this returns + // true. In this case, the |last_aggregated_percent_| and |last_impl_percent_| + // must have value. + bool HasThroughputData() const; + // These functions are called only when HasThroughputData is true. They return + // the throughput value of the corresponding thread, and reset them to nullopt + // to indicate the value has been reported. + int TakeLastAggregatedPercent(); + int TakeLastImplPercent(); + // This could be nullopt even if the HasThroughputData() is true, because it + // could happen that all the frames are generated from the compositor thread. + base::Optional<int> TakeLastMainPercent(); + + uint32_t GetSamplesToNextEventForTesting(int index); + private: // Sampling control. We sample the event here to not throttle the UKM system. // Currently, the same sampling rate is applied to all existing trackers. We @@ -46,10 +63,20 @@ class CC_EXPORT ThroughputUkmReporter { // This is pointing to the LayerTreeHostImpl::ukm_manager_, which is // initialized right after the LayerTreeHostImpl is created. So when this - // pointer is initialized, there should be no trackers yet. Moreover, the - // LayerTreeHostImpl::ukm_manager_ lives as long as the LayerTreeHostImpl, so - // this pointer should never be null as long as LayerTreeHostImpl is alive. + // pointer is initialized, there should be no trackers yet. UkmManager* const ukm_manager_; + + // The last "PercentDroppedFrames" reported to UMA. LayerTreeHostImpl will + // read this number and send to the GPU process. When this page is done, we + // will report to UKM using these numbers. Currently only meaningful to the + // kUniversal tracker. + // Possible values: + // 1. A non-negative int value which is the percent of frames dropped. + // 2. base::nullopt: when they are fetched by LayerTreeHostImpl, so that it + // knows that the last value has been reported. + base::Optional<int> last_aggregated_percent_; + base::Optional<int> last_main_percent_; + base::Optional<int> last_impl_percent_; }; } // namespace cc diff --git a/chromium/cc/metrics/video_playback_roughness_reporter.cc b/chromium/cc/metrics/video_playback_roughness_reporter.cc index 8e76345e537..a7b77e99a65 100644 --- a/chromium/cc/metrics/video_playback_roughness_reporter.cc +++ b/chromium/cc/metrics/video_playback_roughness_reporter.cc @@ -4,6 +4,8 @@ #include "cc/metrics/video_playback_roughness_reporter.h" +#include <algorithm> + #include "base/bind_helpers.h" #include "base/metrics/histogram_macros.h" #include "components/viz/common/quads/compositor_frame_metadata.h" @@ -28,6 +30,7 @@ constexpr int VideoPlaybackRoughnessReporter::kMaxWindowSize; constexpr int VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit; constexpr int VideoPlaybackRoughnessReporter::kMinWindowsBeforeSubmit; constexpr int VideoPlaybackRoughnessReporter::kPercentileToSubmit; +constexpr double VideoPlaybackRoughnessReporter::kDesiredWindowDuration; VideoPlaybackRoughnessReporter::VideoPlaybackRoughnessReporter( PlaybackRoughnessReportingCallback reporting_cb) @@ -37,8 +40,7 @@ VideoPlaybackRoughnessReporter::~VideoPlaybackRoughnessReporter() = default; double VideoPlaybackRoughnessReporter::ConsecutiveFramesWindow::roughness() const { - return root_mean_square_error.InMicrosecondsF() / - intended_duration.InMicrosecondsF(); + return root_mean_square_error.InMillisecondsF(); } VideoPlaybackRoughnessReporter::FrameInfo::FrameInfo() = default; @@ -56,17 +58,10 @@ void VideoPlaybackRoughnessReporter::FrameSubmitted( FrameInfo info; info.token = token; - info.decode_time.emplace(); - if (!frame.metadata()->GetTimeTicks( - media::VideoFrameMetadata::DECODE_END_TIME, - &info.decode_time.value())) { - info.decode_time.reset(); - } + info.decode_time = frame.metadata()->decode_end_time; - info.intended_duration.emplace(); - if (frame.metadata()->GetTimeDelta( - media::VideoFrameMetadata::WALLCLOCK_FRAME_DURATION, - &info.intended_duration.value())) { + info.intended_duration = frame.metadata()->wallclock_frame_duration; + if (info.intended_duration) { if (render_interval > info.intended_duration.value()) { // In videos with FPS higher than display refresh rate we acknowledge // the fact that some frames will be dropped upstream and frame's intended @@ -74,27 +69,28 @@ void VideoPlaybackRoughnessReporter::FrameSubmitted( info.intended_duration = render_interval; } - // Adjust frame window size to fit about 0.5 seconds of playback - double win_size = - std::round(0.5 / info.intended_duration.value().InSecondsF()); + // Adjust frame window size to fit about 1 second of playback + double win_size = std::round(kDesiredWindowDuration / + info.intended_duration.value().InSecondsF()); frames_window_size_ = std::max(kMinWindowSize, static_cast<int>(win_size)); frames_window_size_ = std::min(frames_window_size_, kMaxWindowSize); - } else { - info.intended_duration.reset(); } + frames_.push_back(info); } void VideoPlaybackRoughnessReporter::FramePresented(TokenType token, - base::TimeTicks timestamp) { + base::TimeTicks timestamp, + bool reliable_timestamp) { for (auto it = frames_.rbegin(); it != frames_.rend(); it++) { FrameInfo& info = *it; if (token == it->token) { - info.presentation_time = timestamp; if (info.decode_time.has_value()) { auto time_since_decode = timestamp - info.decode_time.value(); UMA_HISTOGRAM_TIMES("Media.VideoFrameSubmitter", time_since_decode); } + if (reliable_timestamp) + info.presentation_time = timestamp; break; } if (viz::FrameTokenGT(token, it->token)) diff --git a/chromium/cc/metrics/video_playback_roughness_reporter.h b/chromium/cc/metrics/video_playback_roughness_reporter.h index caddf6a3922..d001df91d7c 100644 --- a/chromium/cc/metrics/video_playback_roughness_reporter.h +++ b/chromium/cc/metrics/video_playback_roughness_reporter.h @@ -25,7 +25,7 @@ using PlaybackRoughnessReportingCallback = base::RepeatingCallback< // This class tracks moments when each frame was submitted // and when it was displayed. Then series of frames split into groups -// of consecutive frames, where each group takes about 1/2 second of playback. +// of consecutive frames, where each group takes about one second of playback. // Such groups also called 'frame windows'. Each windows is assigned a roughness // score that measures how far playback smoothness was from the ideal playback. // Information about several windows and their roughness score is aggregated @@ -46,7 +46,9 @@ class CC_EXPORT VideoPlaybackRoughnessReporter { void FrameSubmitted(TokenType token, const media::VideoFrame& frame, base::TimeDelta render_interval); - void FramePresented(TokenType token, base::TimeTicks timestamp); + void FramePresented(TokenType token, + base::TimeTicks timestamp, + bool reliable_timestamp); void ProcessFrameWindow(); void Reset(); @@ -54,13 +56,13 @@ class CC_EXPORT VideoPlaybackRoughnessReporter { static constexpr int kMinWindowSize = 6; // An upper bund on how many frames can be in ConsecutiveFramesWindow - static constexpr int kMaxWindowSize = 40; + static constexpr int kMaxWindowSize = 60; // How many frame windows should be observed before reporting smoothness // due to playback time. - // 1/2 a second per window, 200 windows. It means smoothness will be reported + // 1 second per window, 100 windows. It means smoothness will be reported // for every 100 seconds of playback. - static constexpr int kMaxWindowsBeforeSubmit = 200; + static constexpr int kMaxWindowsBeforeSubmit = 100; // How many frame windows should be observed to report soothness on last // time before the destruction of the reporter. @@ -72,6 +74,13 @@ class CC_EXPORT VideoPlaybackRoughnessReporter { static_assert(kPercentileToSubmit > 0 && kPercentileToSubmit < 100, "invalid percentile value"); + // Desired duration of ConsecutiveFramesWindow in seconds. + // This value and the video FPS are being used when calculating actual + // number of frames in the ConsecutiveFramesWindow. + // kMinWindowSize and kMaxWindowSize put bounds to the window length + // and superseed this value. + static constexpr double kDesiredWindowDuration = 1.0; + private: friend class VideoPlaybackRoughnessReporterTest; struct FrameInfo { diff --git a/chromium/cc/metrics/video_playback_roughness_reporter_unittest.cc b/chromium/cc/metrics/video_playback_roughness_reporter_unittest.cc index e93cbfc3d61..053c1e77d35 100644 --- a/chromium/cc/metrics/video_playback_roughness_reporter_unittest.cc +++ b/chromium/cc/metrics/video_playback_roughness_reporter_unittest.cc @@ -5,6 +5,7 @@ #include "cc/metrics/video_playback_roughness_reporter.h" #include <algorithm> +#include <memory> #include <random> #include <vector> @@ -36,16 +37,21 @@ class VideoPlaybackRoughnessReporterTest : public ::testing::Test { scoped_refptr<VideoFrame> MakeFrame(base::TimeDelta duration) { scoped_refptr<VideoFrame> result = media::VideoFrame::CreateColorFrame( gfx::Size(4, 4), 0x80, 0x80, 0x80, base::TimeDelta()); - result->metadata()->SetTimeDelta( - VideoFrameMetadata::WALLCLOCK_FRAME_DURATION, duration); + result->metadata()->wallclock_frame_duration = duration; return result; } ::testing::AssertionResult CheckSizes() { - if (reporter()->frames_.size() > 80u) - return ::testing::AssertionFailure() - << "frames " << reporter()->frames_.size(); - if (reporter()->worst_windows_.size() > 20u) + size_t max_frames = + 2 * size_t{VideoPlaybackRoughnessReporter::kMaxWindowSize}; + if (reporter()->frames_.size() > max_frames) + return ::testing::AssertionFailure(); + + constexpr int max_worst_windows_size = + 1 + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * + (100 - VideoPlaybackRoughnessReporter::kPercentileToSubmit) / + 100; + if (reporter()->worst_windows_.size() > max_worst_windows_size) return ::testing::AssertionFailure() << "windows " << reporter()->worst_windows_.size(); return ::testing::AssertionSuccess(); @@ -60,7 +66,7 @@ class VideoPlaybackRoughnessReporterTest : public ::testing::Test { base::TimeDelta duration = vsync * frame_cadence; auto frame = MakeFrame(ideal_duration); reporter()->FrameSubmitted(idx, *frame, vsync); - reporter()->FramePresented(idx, time); + reporter()->FramePresented(idx, time, true); reporter()->ProcessFrameWindow(); time += duration; } @@ -83,7 +89,7 @@ class VideoPlaybackRoughnessReporterTest : public ::testing::Test { int presented_idx = idx - i; int frame_cadence = cadence[presented_idx % cadence.size()]; base::TimeDelta duration = vsync * frame_cadence; - reporter()->FramePresented(presented_idx, time); + reporter()->FramePresented(presented_idx, time, true); time += duration; } } @@ -98,13 +104,13 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BestCase24fps) { int fps = 24; SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0118, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 5.9, 0.1); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 10; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 10; NormalRun(fps, 60, {2, 3}, frames_to_run); EXPECT_EQ(call_count, 1); } @@ -114,29 +120,90 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BestCase24fpsOn120Hz) { int fps = 24; SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 0.0, 0.1); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 10; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 10; NormalRun(fps, 120, {5}, frames_to_run); EXPECT_EQ(call_count, 1); } +TEST_F(VideoPlaybackRoughnessReporterTest, BestCase30fps) { + int call_count = 0; + int fps = 30; + SetReportingCallabck( + [&](int size, base::TimeDelta duration, double roughness) { + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 0.0, 0.1); + call_count++; + }); + int frames_to_run = + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; + NormalRun(fps, 60, {2}, frames_to_run); + EXPECT_EQ(call_count, 1); +} + +// This cadence pattern was used in the small user study and was found +// to be perceived by participants as not as good as ideal 30fps playback but +// better than the pattern from UserStudyBad. +// The main characteristic of this test is that cadence breaks by having a frame +// shown only once, but the very next frame is being shown 3 times thus +// fixing the synchronization. +TEST_F(VideoPlaybackRoughnessReporterTest, UserStudyOkay) { + int call_count = 0; + int fps = 30; + SetReportingCallabck( + [&](int size, base::TimeDelta duration, double roughness) { + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 4.3, 0.1); + call_count++; + }); + int frames_to_run = + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; + NormalRun(fps, 60, {2, 2, 2, 2, 2, 2, 1, 3, 2, 2, 2, 2, 2, 2, 2}, + frames_to_run); + EXPECT_EQ(call_count, 1); +} + +// This cadence pattern was used in the small user study and was found +// to be perceived as worst of all options in the study. +// The main characteristic of this test is that cadence breaks by having a frame +// shown only once, and it takes 2 more frames for a frame that is shown 3 times +// thus fixing the synchronization. +TEST_F(VideoPlaybackRoughnessReporterTest, UserStudyBad) { + int call_count = 0; + int fps = 30; + SetReportingCallabck( + [&](int size, base::TimeDelta duration, double roughness) { + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 7.46, 0.1); + call_count++; + }); + int frames_to_run = + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; + NormalRun(fps, 60, {2, 2, 2, 2, 2, 1, 2, 2, 3, 2, 2, 2, 2, 2, 2}, + frames_to_run); + EXPECT_EQ(call_count, 1); +} + TEST_F(VideoPlaybackRoughnessReporterTest, Glitchy24fps) { int call_count = 0; int fps = 24; SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0264, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 14.8, 0.1); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 1; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; NormalRun(fps, 60, {2, 3, 1, 3, 2, 4, 2, 3, 2, 3, 3, 3}, frames_to_run); EXPECT_EQ(call_count, 1); } @@ -146,13 +213,13 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BestCase60fps) { int fps = 60; SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 0.0, 0.1); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 1; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; NormalRun(fps, 60, {1}, frames_to_run); EXPECT_EQ(call_count, 1); } @@ -162,13 +229,13 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BestCase50fps) { int fps = 50; SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0163, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 8.1, 01); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 1; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 1; NormalRun(fps, 60, {1, 1, 1, 1, 2}, frames_to_run); EXPECT_EQ(call_count, 1); } @@ -177,19 +244,18 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BestCase50fps) { // get any result we need. TEST_F(VideoPlaybackRoughnessReporterTest, PredictableRoughnessValue) { int fps = 12; - int frames_in_window = fps / 2; + int frames_in_window = fps; int call_count = 0; - double intended_roughness = 0.042; + double intended_roughness = 4.2; base::TimeDelta vsync = base::TimeDelta::FromSecondsD(1.0 / fps); // Calculating the error value that needs to be injected into one frame // in order to get desired roughness. - base::TimeDelta error = - std::sqrt(intended_roughness * intended_roughness * frames_in_window) * - frames_in_window * vsync; + base::TimeDelta error = base::TimeDelta::FromMillisecondsD( + std::sqrt(intended_roughness * intended_roughness * frames_in_window)); auto callback = [&](int size, base::TimeDelta duration, double roughness) { ASSERT_EQ(frames_in_window, size); - ASSERT_NEAR(roughness, intended_roughness, 0.0001); + ASSERT_NEAR(roughness, intended_roughness, 0.1); call_count++; }; SetReportingCallabck(callback); @@ -204,7 +270,7 @@ TEST_F(VideoPlaybackRoughnessReporterTest, PredictableRoughnessValue) { auto frame = MakeFrame(vsync); reporter()->FrameSubmitted(token, *frame, vsync); - reporter()->FramePresented(token++, time); + reporter()->FramePresented(token++, time, true); reporter()->ProcessFrameWindow(); } } @@ -216,22 +282,22 @@ TEST_F(VideoPlaybackRoughnessReporterTest, PredictableRoughnessValue) { TEST_F(VideoPlaybackRoughnessReporterTest, TakingPercentile) { int token = 0; int fps = 12; - int frames_in_window = fps / 2; + int frames_in_window = fps; int call_count = 0; int win_count = 100; base::TimeDelta vsync = base::TimeDelta::FromSecondsD(1.0 / fps); std::vector<double> targets; targets.reserve(win_count); for (int i = 0; i < win_count; i++) - targets.push_back(i * 0.0001); + targets.push_back(i * 0.1); double expected_roughness = - VideoPlaybackRoughnessReporter::kPercentileToSubmit * 0.0001; + VideoPlaybackRoughnessReporter::kPercentileToSubmit * 0.1; std::mt19937 rnd(1); std::shuffle(targets.begin(), targets.end(), rnd); auto callback = [&](int size, base::TimeDelta duration, double roughness) { ASSERT_EQ(frames_in_window, size); - ASSERT_NEAR(roughness, expected_roughness, 0.00001); + ASSERT_NEAR(roughness, expected_roughness, 0.05); call_count++; }; SetReportingCallabck(callback); @@ -240,9 +306,8 @@ TEST_F(VideoPlaybackRoughnessReporterTest, TakingPercentile) { double roughness = targets[win_idx]; // Calculating the error value that needs to be injected into one frame // in order to get desired roughness. - base::TimeDelta error = - std::sqrt(roughness * roughness * frames_in_window) * frames_in_window * - vsync; + base::TimeDelta error = base::TimeDelta::FromMillisecondsD( + std::sqrt(roughness * roughness * frames_in_window)); for (int frame_idx = 0; frame_idx < frames_in_window; frame_idx++) { base::TimeTicks time; @@ -252,7 +317,7 @@ TEST_F(VideoPlaybackRoughnessReporterTest, TakingPercentile) { auto frame = MakeFrame(vsync); reporter()->FrameSubmitted(token, *frame, vsync); - reporter()->FramePresented(token++, time); + reporter()->FramePresented(token++, time, true); reporter()->ProcessFrameWindow(); } } @@ -271,7 +336,7 @@ TEST_F(VideoPlaybackRoughnessReporterTest, LongRunWithoutWindows) { auto frame = MakeFrame(vsync); reporter()->FrameSubmitted(i, *frame, vsync); if (i % 2 == 0) - reporter()->FramePresented(i, base::TimeTicks() + i * vsync); + reporter()->FramePresented(i, base::TimeTicks() + i * vsync, true); reporter()->ProcessFrameWindow(); ASSERT_TRUE(CheckSizes()); } @@ -288,7 +353,24 @@ TEST_F(VideoPlaybackRoughnessReporterTest, PresentingUnknownFrames) { for (int i = 0; i < 10000; i++) { auto frame = MakeFrame(vsync); reporter()->FrameSubmitted(i, *frame, vsync); - reporter()->FramePresented(i + 100000, base::TimeTicks() + i * vsync); + reporter()->FramePresented(i + 100000, base::TimeTicks() + i * vsync, true); + reporter()->ProcessFrameWindow(); + ASSERT_TRUE(CheckSizes()); + } + EXPECT_EQ(call_count, 0); +} + +// Test that the reporter is ignoring frames with unreliable +// presentation timestamp. +TEST_F(VideoPlaybackRoughnessReporterTest, IgnoringUnreliableTimings) { + int call_count = 0; + base::TimeDelta vsync = base::TimeDelta::FromMilliseconds(1); + SetReportingCallabck([&](int size, base::TimeDelta duration, + double roughness) { call_count++; }); + for (int i = 0; i < 10000; i++) { + auto frame = MakeFrame(vsync); + reporter()->FrameSubmitted(i, *frame, vsync); + reporter()->FramePresented(i, base::TimeTicks() + i * vsync, false); reporter()->ProcessFrameWindow(); ASSERT_TRUE(CheckSizes()); } @@ -307,7 +389,7 @@ TEST_F(VideoPlaybackRoughnessReporterTest, ReportingInReset) { // Set number of frames insufficient for reporting in Reset() int frames_to_run = - VideoPlaybackRoughnessReporter::kMinWindowsBeforeSubmit * fps / 2 - 1; + VideoPlaybackRoughnessReporter::kMinWindowsBeforeSubmit * fps - 1; NormalRun(fps, 60, {1}, frames_to_run); // No calls since, not enough windows were reported EXPECT_EQ(call_count, 0); @@ -318,7 +400,7 @@ TEST_F(VideoPlaybackRoughnessReporterTest, ReportingInReset) { // Set number of frames sufficient for reporting in Reset() frames_to_run = - VideoPlaybackRoughnessReporter::kMinWindowsBeforeSubmit * fps / 2 + 1; + VideoPlaybackRoughnessReporter::kMinWindowsBeforeSubmit * fps + 1; NormalRun(fps, 60, {1}, frames_to_run); // No calls since, not enough windows were reported @@ -338,27 +420,27 @@ TEST_F(VideoPlaybackRoughnessReporterTest, BatchPresentation) { // Try 60 fps SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 0.0, 0.1); call_count++; }); int frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 10; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 10; BatchPresentationRun(fps, 60, {1}, frames_to_run); EXPECT_EQ(call_count, 1); // Try 24fps SetReportingCallabck( [&](int size, base::TimeDelta duration, double roughness) { - ASSERT_EQ(size, fps / 2); - ASSERT_NEAR(duration.InMillisecondsF(), 500.0, 1.0); - ASSERT_NEAR(roughness, 0.0118, 0.0001); + ASSERT_EQ(size, fps); + ASSERT_NEAR(duration.InMillisecondsF(), 1000.0, 1.0); + ASSERT_NEAR(roughness, 5.9, 0.1); call_count++; }); fps = 24; frames_to_run = - VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps / 2 + 10; + VideoPlaybackRoughnessReporter::kMaxWindowsBeforeSubmit * fps + 10; BatchPresentationRun(fps, 60, {2, 3}, frames_to_run); EXPECT_EQ(call_count, 2); } |