| // Copyright 2015 The Chromium Authors |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| #include "cc/metrics/compositor_frame_reporting_controller.h" |
| |
| #include <algorithm> |
| #include <memory> |
| #include <optional> |
| #include <string> |
| #include <utility> |
| #include <vector> |
| |
| #include "base/feature_list.h" |
| #include "base/rand_util.h" |
| #include "base/strings/strcat.h" |
| #include "base/strings/string_number_conversions.h" |
| #include "base/test/metrics/histogram_tester.h" |
| #include "base/test/scoped_feature_list.h" |
| #include "base/test/simple_test_tick_clock.h" |
| #include "base/test/test_trace_processor.h" |
| #include "base/time/time.h" |
| #include "cc/base/features.h" |
| #include "cc/metrics/event_metrics.h" |
| #include "cc/metrics/frame_sequence_metrics.h" |
| #include "cc/metrics/frame_sequence_tracker_collection.h" |
| #include "cc/scheduler/commit_earlyout_reason.h" |
| #include "cc/scheduler/scheduler.h" |
| #include "components/viz/common/frame_timing_details.h" |
| #include "components/viz/common/quads/compositor_frame_metadata.h" |
| #include "testing/gmock/include/gmock/gmock.h" |
| #include "testing/gtest/include/gtest/gtest.h" |
| #include "ui/events/types/scroll_input_type.h" |
| |
| namespace cc { |
| namespace { |
| |
| using ::testing::Each; |
| using ::testing::IsEmpty; |
| using ::testing::NotNull; |
| using SmoothEffectDrivingThread = FrameInfo::SmoothEffectDrivingThread; |
| |
| class TestCompositorFrameReportingController |
| : public CompositorFrameReportingController { |
| public: |
| explicit TestCompositorFrameReportingController( |
| bool is_trees_in_viz_client = false) |
| : CompositorFrameReportingController( |
| /*should_report_histograms=*/true, |
| /*should_report_ukm=*/false, |
| /*layer_tree_host_id=*/1, |
| /*is_trees_in_viz_client=*/is_trees_in_viz_client) {} |
| |
| TestCompositorFrameReportingController( |
| const TestCompositorFrameReportingController& controller) = delete; |
| |
| TestCompositorFrameReportingController& operator=( |
| const TestCompositorFrameReportingController& controller) = delete; |
| |
| int ActiveReporters() { |
| int count = 0; |
| for (int i = 0; i < PipelineStage::kNumPipelineStages; ++i) { |
| if (ReportersForTesting()[i]) { |
| ++count; |
| } |
| } |
| return count; |
| } |
| |
| void ResetReporters() { |
| for (int i = 0; i < PipelineStage::kNumPipelineStages; ++i) { |
| ReportersForTesting()[i] = nullptr; |
| } |
| } |
| |
| size_t GetBlockingReportersCount() { |
| size_t count = 0; |
| const PipelineStage kStages[] = { |
| PipelineStage::kBeginImplFrame, |
| PipelineStage::kBeginMainFrame, |
| PipelineStage::kCommit, |
| PipelineStage::kActivate, |
| }; |
| for (auto stage : kStages) { |
| auto& reporter = ReportersForTesting()[stage]; |
| if (reporter && |
| reporter->partial_update_dependents_size_for_testing() > 0) { |
| ++count; |
| } |
| } |
| return count; |
| } |
| |
| size_t GetBlockedReportersCount() { |
| size_t count = 0; |
| const PipelineStage kStages[] = { |
| PipelineStage::kBeginImplFrame, |
| PipelineStage::kBeginMainFrame, |
| PipelineStage::kCommit, |
| PipelineStage::kActivate, |
| }; |
| for (auto stage : kStages) { |
| auto& reporter = ReportersForTesting()[stage]; |
| if (reporter) |
| count += reporter->partial_update_dependents_size_for_testing(); |
| } |
| return count; |
| } |
| |
| size_t GetAdoptedReportersCount() { |
| size_t count = 0; |
| const PipelineStage kStages[] = { |
| PipelineStage::kBeginImplFrame, |
| PipelineStage::kBeginMainFrame, |
| PipelineStage::kCommit, |
| PipelineStage::kActivate, |
| }; |
| for (auto stage : kStages) { |
| auto& reporter = ReportersForTesting()[stage]; |
| if (reporter) |
| count += reporter->owned_partial_update_dependents_size_for_testing(); |
| } |
| return count; |
| } |
| |
| void trees_in_viz_client(bool new_value) { |
| set_trees_in_viz_client_for_testing(new_value); |
| } |
| }; |
| |
| class CompositorFrameReportingControllerTest : public testing::Test { |
| public: |
| CompositorFrameReportingControllerTest() |
| : current_id_(1, 1), tracker_collection_(false) { |
| test_tick_clock_.SetNowTicks(base::TimeTicks::Now()); |
| reporting_controller_.set_tick_clock(&test_tick_clock_); |
| args_ = SimulateBeginFrameArgs(current_id_); |
| reporting_controller_.SetFrameSorter(&frame_sorter_); |
| reporting_controller_.SetFrameSequenceTrackerCollection( |
| &tracker_collection_); |
| } |
| |
| // The following functions simulate the actions that would |
| // occur for each phase of the reporting controller. |
| void SimulateBeginImplFrame() { |
| IncrementCurrentId(); |
| begin_impl_time_ = AdvanceNowByMs(10); |
| reporting_controller_.WillBeginImplFrame(args_, |
| /*will_throttle_main=*/false); |
| } |
| |
| void SimulateBeginMainFrame() { |
| if (!reporting_controller_ |
| .ReportersForTesting()[CompositorFrameReportingController:: |
| PipelineStage::kBeginImplFrame]) { |
| SimulateBeginImplFrame(); |
| } |
| CHECK(reporting_controller_ |
| .ReportersForTesting()[CompositorFrameReportingController:: |
| PipelineStage::kBeginImplFrame]); |
| begin_main_time_ = AdvanceNowByMs(10); |
| reporting_controller_.WillBeginMainFrame(args_); |
| begin_main_start_time_ = AdvanceNowByMs(10); |
| } |
| |
| void SimulateCommit(std::unique_ptr<BeginMainFrameMetrics> blink_breakdown) { |
| if (!reporting_controller_ |
| .ReportersForTesting()[CompositorFrameReportingController:: |
| PipelineStage::kBeginMainFrame]) { |
| SimulateBeginMainFrame(); |
| } |
| CHECK(reporting_controller_ |
| .ReportersForTesting()[CompositorFrameReportingController:: |
| PipelineStage::kBeginMainFrame]); |
| reporting_controller_.BeginMainFrameStarted(begin_main_start_time_); |
| reporting_controller_.NotifyReadyToCommit(std::move(blink_breakdown)); |
| begin_commit_time_ = AdvanceNowByMs(10); |
| reporting_controller_.WillCommit(); |
| end_commit_time_ = AdvanceNowByMs(10); |
| reporting_controller_.DidCommit(); |
| } |
| |
| void SimulateActivate() { |
| if (!reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kCommit]) { |
| SimulateCommit(nullptr); |
| } |
| CHECK(reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kCommit]); |
| begin_activation_time_ = AdvanceNowByMs(10); |
| reporting_controller_.WillActivate(); |
| end_activation_time_ = AdvanceNowByMs(10); |
| reporting_controller_.DidActivate(); |
| last_activated_id_ = current_id_; |
| } |
| |
| void SimulateSubmitCompositorFrame(EventMetricsSet events_metrics) { |
| if (!reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kActivate]) { |
| SimulateActivate(); |
| } |
| CHECK(reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kActivate]); |
| submit_time_ = AdvanceNowByMs(10); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, submit_time_}; |
| submit_info.events_metrics = std::move(events_metrics); |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| last_activated_id_); |
| } |
| |
| void SimulatePresentCompositorFrame() { |
| SimulateSubmitCompositorFrame({}); |
| viz::FrameTimingDetails details = {}; |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| } |
| |
| viz::BeginFrameArgs SimulateBeginFrameArgs(viz::BeginFrameId frame_id) { |
| args_ = viz::BeginFrameArgs(); |
| args_.frame_id = frame_id; |
| args_.frame_time = AdvanceNowByMs(10); |
| args_.interval = base::Milliseconds(16); |
| current_id_ = frame_id; |
| return args_; |
| } |
| |
| std::unique_ptr<BeginMainFrameMetrics> BuildBlinkBreakdown() { |
| auto breakdown = std::make_unique<BeginMainFrameMetrics>(); |
| breakdown->handle_input_events = base::Microseconds(10); |
| breakdown->animate = base::Microseconds(9); |
| breakdown->style_update = base::Microseconds(8); |
| breakdown->layout_update = base::Microseconds(7); |
| breakdown->compositing_inputs = base::Microseconds(6); |
| breakdown->prepaint = base::Microseconds(5); |
| breakdown->paint = base::Microseconds(3); |
| breakdown->composite_commit = base::Microseconds(2); |
| breakdown->update_layers = base::Microseconds(1); |
| |
| // Advance now by the sum of the breakdowns. |
| AdvanceNowByMs(10 + 9 + 8 + 7 + 6 + 5 + 3 + 2 + 1); |
| |
| return breakdown; |
| } |
| |
| viz::FrameTimingDetails BuildVizBreakdown() { |
| viz::FrameTimingDetails viz_breakdown; |
| viz_breakdown.received_compositor_frame_timestamp = AdvanceNowByMs(1); |
| viz_breakdown.draw_start_timestamp = AdvanceNowByMs(2); |
| viz_breakdown.swap_timings.swap_start = AdvanceNowByMs(3); |
| viz_breakdown.swap_timings.swap_end = AdvanceNowByMs(4); |
| viz_breakdown.presentation_feedback.timestamp = AdvanceNowByMs(5); |
| return viz_breakdown; |
| } |
| |
| void IncrementCurrentId() { |
| current_id_.sequence_number++; |
| args_.frame_id = current_id_; |
| } |
| |
| base::TimeTicks AdvanceNowByMs(int64_t advance_ms) { |
| test_tick_clock_.Advance(base::Microseconds(advance_ms)); |
| return test_tick_clock_.NowTicks(); |
| } |
| |
| std::unique_ptr<EventMetrics> SetupEventMetrics( |
| std::unique_ptr<EventMetrics> metrics) { |
| if (metrics) { |
| AdvanceNowByMs(10); |
| metrics->SetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kRendererCompositorStarted); |
| AdvanceNowByMs(10); |
| metrics->SetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kRendererCompositorFinished); |
| } |
| return metrics; |
| } |
| |
| std::unique_ptr<EventMetrics> CreateEventMetrics( |
| ui::EventType type, |
| std::optional<EventMetrics::TraceId> trace_id) { |
| const base::TimeTicks event_time = AdvanceNowByMs(10); |
| const base::TimeTicks arrived_in_browser_main_timestamp = AdvanceNowByMs(3); |
| AdvanceNowByMs(10); |
| return SetupEventMetrics(EventMetrics::CreateForTesting( |
| type, event_time, arrived_in_browser_main_timestamp, &test_tick_clock_, |
| trace_id)); |
| } |
| |
| std::unique_ptr<EventMetrics> CreateScrollBeginEventMetrics( |
| ui::ScrollInputType input_type) { |
| const base::TimeTicks event_time = AdvanceNowByMs(10); |
| const base::TimeTicks arrived_in_browser_main_timestamp = AdvanceNowByMs(3); |
| AdvanceNowByMs(10); |
| return SetupEventMetrics(ScrollEventMetrics::CreateForTesting( |
| ui::EventType::kGestureScrollBegin, input_type, |
| /*is_inertial=*/false, event_time, arrived_in_browser_main_timestamp, |
| &test_tick_clock_)); |
| } |
| |
| std::unique_ptr<EventMetrics> CreateScrollEndEventMetrics( |
| ui::ScrollInputType input_type, |
| bool is_inertial) { |
| const base::TimeTicks event_time = AdvanceNowByMs(10); |
| const base::TimeTicks arrived_in_browser_main_timestamp = AdvanceNowByMs(3); |
| AdvanceNowByMs(10); |
| std::unique_ptr<EventMetrics> metrics = |
| SetupEventMetrics(ScrollEventMetrics::CreateForTesting( |
| ui::EventType::kGestureScrollEnd, input_type, is_inertial, |
| event_time, arrived_in_browser_main_timestamp, &test_tick_clock_)); |
| metrics->set_caused_frame_update(false); |
| return metrics; |
| } |
| |
| std::unique_ptr<EventMetrics> CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType input_type, |
| bool is_inertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType scroll_update_type, |
| std::optional<EventMetrics::TraceId> trace_id) { |
| const base::TimeTicks event_time = AdvanceNowByMs(10); |
| const base::TimeTicks arrived_in_browser_main_timestamp = AdvanceNowByMs(3); |
| AdvanceNowByMs(10); |
| |
| auto scroll_update = ScrollUpdateEventMetrics::CreateForTesting( |
| ui::EventType::kGestureScrollUpdate, input_type, is_inertial, |
| scroll_update_type, /*delta=*/10.0f, event_time, |
| arrived_in_browser_main_timestamp, &test_tick_clock_, trace_id); |
| scroll_update->set_did_scroll(true); |
| return SetupEventMetrics(std::move(scroll_update)); |
| } |
| |
| std::unique_ptr<EventMetrics> CreatePinchEventMetrics( |
| ui::EventType type, |
| ui::ScrollInputType input_type) { |
| const base::TimeTicks event_time = AdvanceNowByMs(10); |
| AdvanceNowByMs(10); |
| return SetupEventMetrics(PinchEventMetrics::CreateForTesting( |
| type, input_type, event_time, &test_tick_clock_)); |
| } |
| |
| std::vector<base::TimeTicks> GetEventTimestamps( |
| const EventMetrics::List& events_metrics) { |
| std::vector<base::TimeTicks> event_times; |
| event_times.reserve(events_metrics.size()); |
| std::ranges::transform(events_metrics, std::back_inserter(event_times), |
| [](const auto& event_metrics) { |
| return event_metrics->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| }); |
| return event_times; |
| } |
| |
| protected: |
| // Disable sub-sampling to deterministically record histograms under test. |
| base::MetricsSubSampler::ScopedAlwaysSampleForTesting no_subsampling_; |
| |
| // This should be defined before |reporting_controller_| so it is created |
| // before and destroyed after that. |
| base::SimpleTestTickClock test_tick_clock_; |
| |
| viz::BeginFrameArgs args_; |
| viz::BeginFrameId current_id_; |
| viz::BeginFrameId last_activated_id_; |
| base::TimeTicks begin_impl_time_; |
| base::TimeTicks begin_main_time_; |
| base::TimeTicks begin_main_start_time_; |
| base::TimeTicks begin_commit_time_; |
| base::TimeTicks end_commit_time_; |
| base::TimeTicks begin_activation_time_; |
| base::TimeTicks end_activation_time_; |
| base::TimeTicks submit_time_; |
| viz::FrameTokenGenerator current_token_; |
| FrameSorter frame_sorter_; |
| FrameSequenceTrackerCollection tracker_collection_; |
| TestCompositorFrameReportingController reporting_controller_; |
| ::base::test::TracingEnvironment tracing_environment_; |
| }; |
| |
| TEST_F(CompositorFrameReportingControllerTest, ActiveReporterCounts) { |
| // Check that there are no leaks with the CompositorFrameReporter |
| // objects no matter what the sequence of scheduled actions is |
| // Note that due to DCHECKs in WillCommit(), WillActivate(), etc., it |
| // is impossible to have 2 reporters both in BMF or Commit |
| |
| // Tests Cases: |
| // - 2 Reporters at Activate phase |
| // - 2 back-to-back BeginImplFrames |
| // - 4 Simultaneous Reporters |
| |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| // BF |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| reporting_controller_.OnFinishImplFrame(args_1.frame_id, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_1.frame_id, |
| FrameSkippedReason::kNoDamage); |
| |
| // BF -> BF |
| // Should replace previous reporter. |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| reporting_controller_.OnFinishImplFrame(args_2.frame_id, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_2.frame_id, |
| FrameSkippedReason::kNoDamage); |
| |
| // BF -> BMF -> BF |
| // Should add new reporter. |
| reporting_controller_.WillBeginMainFrame(args_2); |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| |
| // BF -> BMF -> BF -> Commit |
| // Should stay same. |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| |
| // BF -> BMF -> BF -> Commit -> BMF -> Activate -> Commit -> Activation |
| // Having two reporters at Activate phase should delete the older one. |
| reporting_controller_.WillBeginMainFrame(args_3); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| |
| // There is a reporters tracking frame_3 in BeginMain state and one reporter |
| // for frame_2 in activate state. |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| // Reporter in activate state for frame_2 is overwritten by the reporter for |
| // frame_3. |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| |
| last_activated_id_ = current_id_3; |
| SubmitInfo submit_info; |
| submit_info.time = AdvanceNowByMs(10); |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_3, |
| last_activated_id_); |
| EXPECT_EQ(0, reporting_controller_.ActiveReporters()); |
| |
| // Start a frame and take it all the way to the activate stage. |
| SimulateActivate(); |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| |
| // Start another frame and let it progress up to the commit stage. |
| SimulateCommit(nullptr); |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| |
| // Start the next frame, and let it progress up to the main-frame. |
| SimulateBeginMainFrame(); |
| EXPECT_EQ(3, reporting_controller_.ActiveReporters()); |
| |
| // Start the next frame. |
| SimulateBeginImplFrame(); |
| EXPECT_EQ(4, reporting_controller_.ActiveReporters()); |
| |
| reporting_controller_.OnFinishImplFrame(args_.frame_id, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_.frame_id, |
| FrameSkippedReason::kNoDamage); |
| |
| // Any additional BeginImplFrame's would be ignored. |
| SimulateBeginImplFrame(); |
| EXPECT_EQ(4, reporting_controller_.ActiveReporters()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| StopRequestingFramesCancelsInFlightFrames) { |
| base::HistogramTester histogram_tester; |
| |
| // 2 reporters active. |
| SimulateActivate(); |
| SimulateCommit(nullptr); |
| |
| reporting_controller_.OnStoppedRequestingBeginFrames(); |
| reporting_controller_.ResetReporters(); |
| histogram_tester.ExpectBucketCount( |
| "CompositorLatency2.Type", |
| CompositorFrameReporter::FrameReportType::kDroppedFrame, 0); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| SubmittedFrameHistogramReporting) { |
| base::HistogramTester histogram_tester; |
| |
| // 2 reporters active. |
| SimulateActivate(); |
| SimulateCommit(nullptr); |
| |
| // Submitting and Presenting the next reporter which will be a normal frame. |
| SimulatePresentCompositorFrame(); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| |
| // Submitting the next reporter will be replaced as a result of a new commit. |
| // And this will be reported for all stage before activate as a missed frame. |
| SimulateCommit(nullptr); |
| // Non Missed frame histogram counts should not change. |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, MainFrameCausedNoDamage) { |
| base::HistogramTester histogram_tester; |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_1, CommitEarlyOutReason::kFinishedNoUpdates); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(current_id_1, |
| FrameSkippedReason::kNoDamage); |
| |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_2); |
| reporting_controller_.OnFinishImplFrame(current_id_2, |
| /*waiting_for_main=*/true); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_2, CommitEarlyOutReason::kFinishedNoUpdates); |
| reporting_controller_.DidNotProduceFrame(current_id_2, |
| FrameSkippedReason::kNoDamage); |
| |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_3); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.SendBeginMainFrameToCommit", 0); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, DidNotProduceFrame) { |
| base::HistogramTester histogram_tester; |
| |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(current_id_1, |
| FrameSkippedReason::kNoDamage); |
| |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_2, |
| /*waiting_for_main=*/true); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_2, |
| current_id_1); |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.SendBeginMainFrameToCommit", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 2); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, MainFrameAborted) { |
| base::HistogramTester histogram_tester; |
| |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_, CommitEarlyOutReason::kFinishedNoUpdates); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| last_activated_id_); |
| |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 0); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, MainFrameAborted2) { |
| base::HistogramTester histogram_tester; |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_2); |
| reporting_controller_.OnFinishImplFrame(current_id_2, |
| /*waiting_for_main=*/true); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_2, CommitEarlyOutReason::kFinishedNoUpdates); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_2, |
| current_id_1); |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 2); |
| SubmitInfo submit_info2 = {2u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_2, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(2, details); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 2); |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_3, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info3 = {3u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_3, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(3, details); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 3); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 3); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 3); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, LongMainFrame) { |
| base::HistogramTester histogram_tester; |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| submit_info.normalized_invalidated_area = 10; |
| |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_1, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1); |
| |
| // Second frame will not have the main frame update ready and will only submit |
| // the Impl update |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_2); |
| reporting_controller_.OnFinishImplFrame(current_id_2, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info2 = {2u, AdvanceNowByMs(10)}; |
| submit_info2.normalized_invalidated_area = 10; |
| |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_2, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(2, details); |
| |
| // The reporting for the second frame is delayed until the main-thread |
| // responds back. |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1); |
| |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_3, |
| /*waiting_for_main=*/true); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| SubmitInfo submit_info3 = {3u, AdvanceNowByMs(10)}; |
| submit_info3.normalized_invalidated_area = 10; |
| |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_3, |
| current_id_2); |
| reporting_controller_.DidPresentCompositorFrame(3, details); |
| |
| // The main-thread responded, so the metrics for |args_2| should now be |
| // reported. |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 3); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 4); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 4); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 4); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, LongMainFrame2) { |
| base::HistogramTester histogram_tester; |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| submit_info.normalized_invalidated_area = 10; |
| |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_1, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1); |
| |
| // The reporting for the second frame is delayed until activation happens. |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_2); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.OnFinishImplFrame(current_id_2, |
| /*waiting_for_main=*/true); |
| |
| SubmitInfo submit_info2 = {2u, AdvanceNowByMs(10)}; |
| submit_info2.normalized_invalidated_area = 10; |
| |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_2, |
| current_id_1); |
| reporting_controller_.DidPresentCompositorFrame(2, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| // The metrics are reported for |args_2| after activation finally happens and |
| // a new frame is submitted. |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_3, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info3 = {3u, AdvanceNowByMs(10)}; |
| submit_info3.normalized_invalidated_area = 10; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_3, |
| current_id_2); |
| reporting_controller_.DidPresentCompositorFrame(3, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "Graphics.Paint.UI.NormalizedInvalidatedArea", 3); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 4); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Commit", 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.EndCommitToActivation", |
| 2); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.Activation", 2); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 4); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 4); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, BlinkBreakdown) { |
| base::HistogramTester histogram_tester; |
| |
| std::unique_ptr<BeginMainFrameMetrics> blink_breakdown = |
| BuildBlinkBreakdown(); |
| SimulateActivate(); |
| SimulateCommit(std::move(blink_breakdown)); |
| SimulatePresentCompositorFrame(); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit", 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.HandleInputEvents", |
| base::Microseconds(10).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.Animate", |
| base::Microseconds(9).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.StyleUpdate", |
| base::Microseconds(8).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.LayoutUpdate", |
| base::Microseconds(7).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.CompositingInputs", |
| base::Microseconds(6).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.Prepaint", |
| base::Microseconds(5).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.Paint", |
| base::Microseconds(3).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.CompositeCommit", |
| base::Microseconds(2).InMilliseconds(), 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SendBeginMainFrameToCommit.UpdateLayers", |
| base::Microseconds(1).InMilliseconds(), 1); |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.SendBeginMainFrameToCommit.BeginMainSentToStarted", |
| 1); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, VizBreakdown) { |
| // Test is mutually-exclusive with ValidateTreesInVizBreakdown, |
| // so it does not apply to TreesInViz mode. |
| if (base::FeatureList::IsEnabled(features::kTreesInViz)) { |
| return; |
| } |
| base::HistogramTester histogram_tester; |
| |
| SimulateSubmitCompositorFrame({}); |
| viz::FrameTimingDetails viz_details = BuildVizBreakdown(); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, viz_details); |
| |
| // Check that the viz timestamps were set corresponding to the values |
| // in BuildVizBreakdown. |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.EndActivateToSubmitCompositorFrame", 10, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame." |
| "SubmitToReceiveCompositorFrame", |
| 1, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame." |
| "ReceivedCompositorFrameToStartDraw", |
| 2, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame." |
| "StartDrawToSwapStart", |
| 3, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame." |
| "SwapStartToSwapEnd", |
| 4, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame." |
| "SwapEndToPresentationCompositorFrame", |
| 5, 1); |
| |
| // Expect the total latency to be equal to the sum of the stages. |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitCompositorFrameToPresentationCompositorFrame", |
| 1 + 2 + 3 + 4 + 5, 1); |
| } |
| |
| class TreesInVizClientCompositorFrameReportingControllerTest |
| : public CompositorFrameReportingControllerTest { |
| public: |
| TreesInVizClientCompositorFrameReportingControllerTest() { |
| reporting_controller_.trees_in_viz_client(true); |
| scoped_feature_list_.InitAndEnableFeature(features::kTreesInViz); |
| } |
| |
| void SimulateSubmitCompositorFrameWithTreesInVizTimingDetails( |
| EventMetricsSet events_metrics) { |
| if (!reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kActivate]) { |
| CompositorFrameReportingControllerTest::SimulateActivate(); |
| } |
| CHECK(reporting_controller_.ReportersForTesting() |
| [CompositorFrameReportingController::PipelineStage::kActivate]); |
| submit_time_ = AdvanceNowByMs(7); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, submit_time_}; |
| submit_info.events_metrics = std::move(events_metrics); |
| submit_info.trees_in_viz_submit_time = AdvanceNowByMs(11); |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| last_activated_id_); |
| } |
| |
| void SimulatePresentCompositorFrameWithTreesInVizTimingDetails() { |
| SimulateSubmitCompositorFrameWithTreesInVizTimingDetails({}); |
| viz::FrameTimingDetails details = {}; |
| // Optional TreesInViz - related timestamps. |
| details.start_update_display_tree = |
| AdvanceNowByMs(35); // Pretend it took a long time |
| details.start_prepare_to_draw = AdvanceNowByMs(2); |
| details.start_draw_layers = AdvanceNowByMs(3); |
| details.submit_compositor_frame = AdvanceNowByMs(5); |
| |
| // Older timestamps |
| details.received_compositor_frame_timestamp = AdvanceNowByMs(6); |
| details.draw_start_timestamp = AdvanceNowByMs(7); |
| details.swap_timings.swap_start = AdvanceNowByMs(8); |
| details.swap_timings.swap_end = AdvanceNowByMs(9); |
| |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| } |
| |
| protected: |
| base::test::ScopedFeatureList scoped_feature_list_; |
| }; |
| |
| TEST_F(TreesInVizClientCompositorFrameReportingControllerTest, |
| ValidateTreesInVizAbortedFrame) { |
| // base::HistogramTester histogram_tester; |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_); |
| |
| // Pretend that we submitted the UpdateDisplayTree. |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| submit_info.trees_in_viz_submit_time = AdvanceNowByMs(13); |
| |
| // Abort the main frame. This sets the impl_frame_finish_time. |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_, CommitEarlyOutReason::kFinishedNoUpdates); |
| |
| // We ge some feedbacks at some later time because we ended up using the |
| // update tree to produce a frame. Should run without crashing. |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| last_activated_id_); |
| } |
| |
| TEST_F(TreesInVizClientCompositorFrameReportingControllerTest, |
| ValidateTreesInVizBreakdown) { |
| base::HistogramTester histogram_tester; |
| |
| // This function will simulate stepping through the entire CFRC flow, |
| // with timestamps added to the stages relevant for TreesInViz. |
| SimulatePresentCompositorFrameWithTreesInVizTimingDetails(); |
| |
| // TreesInViz should introduce the following breakdowns |
| // CC-only stages |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.EndActivateToSubmitUpdateDisplayTree." |
| "EndActivateToDrawLayers", |
| 7, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.EndActivateToSubmitUpdateDisplayTree." |
| "DrawLayersToSubmitUpdateDisplayTree", |
| 11, 1); |
| // CC -> Viz RPC |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "SendUpdateDisplayTreeToReceiveUpdateDisplayTree", |
| 35, 1); |
| // Viz-only stages |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "ReceiveUpdateDisplayTreeToStartPrepareToDraw", |
| 2, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "StartPrepareToDrawToStartDrawLayers", |
| 3, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "StartDrawLayersToSubmitCompositorFrame", |
| 5, 1); |
| |
| // Stages not introduced by TreesInViz should remain accurate. |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "SubmitToReceiveCompositorFrame", |
| 6, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "ReceivedCompositorFrameToStartDraw", |
| 7, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "StartDrawToSwapStart", |
| 8, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "SwapStartToSwapEnd", |
| 9, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame." |
| "SwapEndToPresentationCompositorFrame", |
| 10, 1); |
| |
| // The sum of these values should sum to the total of the stage breakdown. |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.EndActivateToSubmitUpdateDisplayTree", 7 + 11, 1); |
| histogram_tester.ExpectUniqueSample( |
| "CompositorLatency2.SubmitUpdateDisplayTreeToPresentationCompositorFrame", |
| 35 + 2 + 3 + 5 + 6 + 7 + 8 + 9 + 10, 1); |
| } |
| |
| TEST_F(TreesInVizClientCompositorFrameReportingControllerTest, |
| EmitBothBranchesOfHistograms) { |
| base::HistogramTester histogram_tester; |
| |
| // This function will simulate stepping through the entire CFRC flow, |
| // with timestamps added to the stages relevant for TreesInViz. |
| // This emits the TreesInViz branch of histograms. |
| SimulatePresentCompositorFrameWithTreesInVizTimingDetails(); |
| |
| // This emits the normal-path histograms. |
| reporting_controller_.trees_in_viz_client(false); |
| SimulatePresentCompositorFrame(); |
| |
| // Test should not crash. |
| } |
| |
| // If the presentation of the frame happens before deadline. |
| TEST_F(CompositorFrameReportingControllerTest, ReportingMissedDeadlineFrame1) { |
| base::HistogramTester histogram_tester; |
| |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.WillBeginMainFrame(args_); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| current_id_); |
| viz::FrameTimingDetails details = {}; |
| details.presentation_feedback.timestamp = |
| args_.frame_time + args_.interval * 1.5 - base::Microseconds(100); |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.TotalLatency", 1); |
| } |
| |
| // If the presentation of the frame happens after deadline. |
| TEST_F(CompositorFrameReportingControllerTest, ReportingMissedDeadlineFrame2) { |
| base::HistogramTester histogram_tester; |
| |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.WillBeginMainFrame(args_); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| current_id_); |
| viz::FrameTimingDetails details = {}; |
| details.presentation_feedback.timestamp = |
| args_.frame_time + args_.interval * 1.5 + base::Microseconds(100); |
| reporting_controller_.DidPresentCompositorFrame(1, details); |
| |
| histogram_tester.ExpectTotalCount( |
| "CompositorLatency2.BeginImplFrameToSendBeginMainFrame", 1); |
| histogram_tester.ExpectTotalCount("CompositorLatency2.TotalLatency", 1); |
| } |
| |
| // If a compositor animation takes too long and throttles draw |
| TEST_F(CompositorFrameReportingControllerTest, LongCompositorAnimation) { |
| base::HistogramTester histogram_tester; |
| |
| SimulatePresentCompositorFrame(); |
| |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| last_activated_id_); |
| viz::FrameTimingDetails details = {}; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| |
| IncrementCurrentId(); |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_.frame_id, |
| FrameSkippedReason::kDrawThrottled); |
| |
| IncrementCurrentId(); |
| // Flushing the last no damage frame. |
| reporting_controller_.WillBeginImplFrame(args_, /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| EXPECT_EQ(3u, frame_sorter_.total_frames()); |
| EXPECT_EQ(1u, frame_sorter_.total_dropped()); |
| } |
| |
| // Tests that EventLatency total latency histograms are reported properly when a |
| // frame is presented to the user. |
| TEST_F(CompositorFrameReportingControllerTest, |
| EventLatencyTotalForPresentedFrameReported) { |
| base::HistogramTester histogram_tester; |
| |
| std::unique_ptr<EventMetrics> event_metrics_ptrs[] = { |
| CreateEventMetrics(ui::EventType::kTouchPressed, std::nullopt), |
| CreateEventMetrics(ui::EventType::kTouchMoved, std::nullopt), |
| CreateEventMetrics(ui::EventType::kTouchMoved, std::nullopt), |
| }; |
| EXPECT_THAT(event_metrics_ptrs, Each(NotNull())); |
| EventMetrics::List events_metrics( |
| std::make_move_iterator(std::begin(event_metrics_ptrs)), |
| std::make_move_iterator(std::end(event_metrics_ptrs))); |
| std::vector<base::TimeTicks> event_times = GetEventTimestamps(events_metrics); |
| |
| // Submit a compositor frame and notify CompositorFrameReporter of the events |
| // affecting the frame. |
| SimulateSubmitCompositorFrame({std::move(events_metrics), {}, {}}); |
| |
| // Present the submitted compositor frame to the user. |
| const base::TimeTicks presentation_time = AdvanceNowByMs(10); |
| viz::FrameTimingDetails details; |
| details.presentation_feedback.timestamp = presentation_time; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| |
| // Verify that EventLatency histograms are recorded. |
| struct { |
| const char* name; |
| const base::HistogramBase::Count32 count; |
| } expected_counts[] = { |
| {"EventLatency.TouchPressed.TotalLatency", 1}, |
| {"EventLatency.TouchMoved.TotalLatency", 2}, |
| {"EventLatency.TotalLatency", 3}, |
| }; |
| for (const auto& expected_count : expected_counts) { |
| histogram_tester.ExpectTotalCount(expected_count.name, |
| expected_count.count); |
| } |
| |
| struct { |
| const char* name; |
| const base::HistogramBase::Sample32 latency_ms; |
| } expected_latencies[] = { |
| {"EventLatency.TouchPressed.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.TouchMoved.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.TouchMoved.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| }; |
| for (const auto& expected_latency : expected_latencies) { |
| histogram_tester.ExpectBucketCount(expected_latency.name, |
| expected_latency.latency_ms, 1); |
| } |
| } |
| |
| // Tests that EventLatency total latency histograms are reported properly for |
| // scroll events when a frame is presented to the user. |
| TEST_F(CompositorFrameReportingControllerTest, |
| EventLatencyScrollTotalForPresentedFrameReported) { |
| base::HistogramTester histogram_tester; |
| |
| const bool kScrollIsInertial = true; |
| const bool kScrollIsNotInertial = false; |
| std::unique_ptr<EventMetrics> event_metrics_ptrs[] = { |
| CreateScrollBeginEventMetrics(ui::ScrollInputType::kWheel), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, kScrollIsNotInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, kScrollIsNotInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, kScrollIsInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt), |
| CreateScrollBeginEventMetrics(ui::ScrollInputType::kTouchscreen), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kTouchscreen, kScrollIsNotInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kTouchscreen, kScrollIsNotInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt), |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kTouchscreen, kScrollIsInertial, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt), |
| }; |
| EXPECT_THAT(event_metrics_ptrs, Each(NotNull())); |
| EventMetrics::List events_metrics( |
| std::make_move_iterator(std::begin(event_metrics_ptrs)), |
| std::make_move_iterator(std::end(event_metrics_ptrs))); |
| std::vector<base::TimeTicks> event_times = GetEventTimestamps(events_metrics); |
| |
| // Submit a compositor frame and notify CompositorFrameReporter of the events |
| // affecting the frame. |
| SimulateSubmitCompositorFrame({std::move(events_metrics), {}, {}}); |
| |
| // Present the submitted compositor frame to the user. |
| viz::FrameTimingDetails details; |
| details.received_compositor_frame_timestamp = AdvanceNowByMs(10); |
| details.draw_start_timestamp = AdvanceNowByMs(10); |
| details.swap_timings.swap_start = AdvanceNowByMs(10); |
| details.swap_timings.swap_end = AdvanceNowByMs(10); |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| |
| // Verify that EventLatency histograms are recorded. |
| struct { |
| const char* name; |
| const base::HistogramBase::Count32 count; |
| } expected_counts[] = { |
| {"EventLatency.GestureScrollBegin.Wheel.TotalLatency2", 1}, |
| {"EventLatency.FirstGestureScrollUpdate.Wheel.TotalLatency2", 1}, |
| {"EventLatency.GestureScrollUpdate.Wheel.TotalLatency2", 1}, |
| {"EventLatency.InertialGestureScrollUpdate.Wheel.TotalLatency2", 1}, |
| {"EventLatency.GestureScrollBegin.Touchscreen.TotalLatency2", 1}, |
| {"EventLatency.FirstGestureScrollUpdate.Touchscreen.TotalLatency2", 1}, |
| {"EventLatency.GestureScrollUpdate.Touchscreen.TotalLatency", 1}, |
| {"EventLatency.GestureScrollUpdate.Touchscreen.TotalLatency2", 1}, |
| {"EventLatency.InertialGestureScrollUpdate.Touchscreen.TotalLatency2", 1}, |
| {"EventLatency.GestureScrollBegin.TotalLatency2", 2}, |
| {"EventLatency.GestureScrollBegin.GenerationToBrowserMain", 2}, |
| {"EventLatency.FirstGestureScrollUpdate.TotalLatency2", 2}, |
| {"EventLatency.FirstGestureScrollUpdate.GenerationToBrowserMain", 2}, |
| {"EventLatency.GestureScrollUpdate.TotalLatency2", 2}, |
| {"EventLatency.GestureScrollUpdate.GenerationToBrowserMain", 2}, |
| {"EventLatency.InertialGestureScrollUpdate.TotalLatency2", 2}, |
| {"EventLatency.InertialGestureScrollUpdate.GenerationToBrowserMain", 2}, |
| {"EventLatency.TotalLatency", 8}, |
| }; |
| for (const auto& expected_count : expected_counts) { |
| histogram_tester.ExpectTotalCount(expected_count.name, |
| expected_count.count); |
| } |
| |
| const base::TimeTicks presentation_time = |
| details.presentation_feedback.timestamp; |
| struct { |
| const char* name; |
| const base::HistogramBase::Sample32 latency_ms; |
| } expected_latencies[] = { |
| {"EventLatency.GestureScrollBegin.Wheel.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.FirstGestureScrollUpdate.Wheel.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.GestureScrollUpdate.Wheel.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| {"EventLatency.InertialGestureScrollUpdate.Wheel.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[3]).InMicroseconds())}, |
| {"EventLatency.GestureScrollBegin.Touchscreen.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[4]).InMicroseconds())}, |
| {"EventLatency.FirstGestureScrollUpdate.Touchscreen.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[5]).InMicroseconds())}, |
| {"EventLatency.GestureScrollUpdate.Touchscreen.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[6]).InMicroseconds())}, |
| {"EventLatency.GestureScrollUpdate.Touchscreen.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[6]).InMicroseconds())}, |
| {"EventLatency.InertialGestureScrollUpdate.Touchscreen.TotalLatency2", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[7]).InMicroseconds())}, |
| }; |
| for (const auto& expected_latency : expected_latencies) { |
| histogram_tester.ExpectBucketCount(expected_latency.name, |
| expected_latency.latency_ms, 1); |
| } |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| EventLatencyMainRepaintedScroll) { |
| base::HistogramTester histogram_tester; |
| |
| // Set up two EventMetrics objects. |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| base::TimeTicks start_time_1 = metrics_1->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| // The second EventMetrics does not have set_requires_main_thread_update(). |
| // (It's not very realistic for the same scroll gesture to produce two events |
| // with differing values for this bit, but let's test both conditions here.) |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| metrics_2->set_requires_main_thread_update(); |
| base::TimeTicks start_time_2 = metrics_2->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| // Simulate a frame getting stuck in the main thread. |
| SimulateBeginImplFrame(); |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update with our events from the compositor thread. |
| EventMetrics::List metrics_list; |
| metrics_list.push_back(std::move(metrics_1)); |
| metrics_list.push_back(std::move(metrics_2)); |
| SubmitInfo submit_info = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, {}); |
| |
| // Present the partial update. |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details_1); |
| |
| // Let the main thread finish its work. |
| SimulateCommit(nullptr); |
| SimulateActivate(); |
| |
| // Submit the final update. |
| SimulateBeginImplFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SimulateSubmitCompositorFrame({}); |
| |
| // Present the final update. |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details_2); |
| |
| // metrics_1 did NOT have requires_main_thread_update(), so its latency is |
| // based on the partial-update presentation (details_1). |
| base::TimeDelta expected_latency_1 = |
| details_1.presentation_feedback.timestamp - start_time_1; |
| histogram_tester.ExpectBucketCount( |
| "EventLatency.FirstGestureScrollUpdate.Wheel.TotalLatency2", |
| expected_latency_1.InMicroseconds(), 1); |
| |
| // metrics_2 has requires_main_thread_update(), so its latency is based on the |
| // final-update presentation (details_2). |
| base::TimeDelta expected_latency_2 = |
| details_2.presentation_feedback.timestamp - start_time_2; |
| histogram_tester.ExpectBucketCount( |
| "EventLatency.GestureScrollUpdate.Wheel.TotalLatency2", |
| expected_latency_2.InMicroseconds(), 1); |
| } |
| |
| // Tests that EventLatency total latency histograms are reported properly for |
| // pinch events when a frame is presented to the user. |
| TEST_F(CompositorFrameReportingControllerTest, |
| EventLatencyPinchTotalForPresentedFrameReported) { |
| base::HistogramTester histogram_tester; |
| |
| std::unique_ptr<EventMetrics> event_metrics_ptrs[] = { |
| CreatePinchEventMetrics(ui::EventType::kGesturePinchBegin, |
| ui::ScrollInputType::kWheel), |
| CreatePinchEventMetrics(ui::EventType::kGesturePinchUpdate, |
| ui::ScrollInputType::kWheel), |
| CreatePinchEventMetrics(ui::EventType::kGesturePinchBegin, |
| ui::ScrollInputType::kTouchscreen), |
| CreatePinchEventMetrics(ui::EventType::kGesturePinchUpdate, |
| ui::ScrollInputType::kTouchscreen), |
| }; |
| EXPECT_THAT(event_metrics_ptrs, Each(NotNull())); |
| EventMetrics::List events_metrics( |
| std::make_move_iterator(std::begin(event_metrics_ptrs)), |
| std::make_move_iterator(std::end(event_metrics_ptrs))); |
| std::vector<base::TimeTicks> event_times = GetEventTimestamps(events_metrics); |
| |
| // Submit a compositor frame and notify CompositorFrameReporter of the events |
| // affecting the frame. |
| SimulateSubmitCompositorFrame({std::move(events_metrics), {}, {}}); |
| |
| // Present the submitted compositor frame to the user. |
| viz::FrameTimingDetails details; |
| details.received_compositor_frame_timestamp = AdvanceNowByMs(10); |
| details.draw_start_timestamp = AdvanceNowByMs(10); |
| details.swap_timings.swap_start = AdvanceNowByMs(10); |
| details.swap_timings.swap_end = AdvanceNowByMs(10); |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| |
| // Verify that EventLatency histograms are recorded. |
| struct { |
| const char* name; |
| const base::HistogramBase::Count32 count; |
| } expected_counts[] = { |
| {"EventLatency.GesturePinchBegin.Touchpad.TotalLatency", 1}, |
| {"EventLatency.GesturePinchUpdate.Touchpad.TotalLatency", 1}, |
| {"EventLatency.GesturePinchBegin.Touchscreen.TotalLatency", 1}, |
| {"EventLatency.GesturePinchUpdate.Touchscreen.TotalLatency", 1}, |
| {"EventLatency.TotalLatency", 4}, |
| }; |
| for (const auto& expected_count : expected_counts) { |
| histogram_tester.ExpectTotalCount(expected_count.name, |
| expected_count.count); |
| } |
| |
| const base::TimeTicks presentation_time = |
| details.presentation_feedback.timestamp; |
| struct { |
| const char* name; |
| const base::HistogramBase::Sample32 latency_ms; |
| } expected_latencies[] = { |
| {"EventLatency.GesturePinchBegin.Touchpad.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.GesturePinchUpdate.Touchpad.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.GesturePinchBegin.Touchscreen.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| {"EventLatency.GesturePinchUpdate.Touchscreen.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[3]).InMicroseconds())}, |
| }; |
| for (const auto& expected_latency : expected_latencies) { |
| histogram_tester.ExpectBucketCount(expected_latency.name, |
| expected_latency.latency_ms, 1); |
| } |
| } |
| |
| // Tests that EventLatency histograms for events of a dropped frame are reported |
| // in the first subsequent presented frame. |
| TEST_F(CompositorFrameReportingControllerTest, |
| EventLatencyForDidNotPresentFrameReportedOnNextPresent) { |
| base::HistogramTester histogram_tester; |
| |
| std::unique_ptr<EventMetrics> event_metrics_ptrs[] = { |
| CreateEventMetrics(ui::EventType::kTouchPressed, std::nullopt), |
| CreateEventMetrics(ui::EventType::kTouchMoved, std::nullopt), |
| CreateEventMetrics(ui::EventType::kTouchMoved, std::nullopt), |
| }; |
| EXPECT_THAT(event_metrics_ptrs, Each(NotNull())); |
| EventMetrics::List events_metrics( |
| std::make_move_iterator(std::begin(event_metrics_ptrs)), |
| std::make_move_iterator(std::end(event_metrics_ptrs))); |
| std::vector<base::TimeTicks> event_times = GetEventTimestamps(events_metrics); |
| |
| // Submit a compositor frame and notify CompositorFrameReporter of the events |
| // affecting the frame. |
| SimulateSubmitCompositorFrame({std::move(events_metrics), {}, {}}); |
| |
| // Submit another compositor frame. |
| IncrementCurrentId(); |
| SimulateSubmitCompositorFrame({}); |
| |
| // Present the second compositor frame to the user, dropping the first one. |
| const base::TimeTicks presentation_time = AdvanceNowByMs(10); |
| viz::FrameTimingDetails details; |
| details.presentation_feedback.timestamp = presentation_time; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, details); |
| |
| // Verify that EventLatency histograms for the first frame (dropped) are |
| // recorded using the presentation time of the second frame (presented). |
| struct { |
| const char* name; |
| const base::HistogramBase::Count32 count; |
| } expected_counts[] = { |
| {"EventLatency.TouchPressed.TotalLatency", 1}, |
| {"EventLatency.TouchMoved.TotalLatency", 2}, |
| {"EventLatency.TotalLatency", 3}, |
| }; |
| for (const auto& expected_count : expected_counts) { |
| histogram_tester.ExpectTotalCount(expected_count.name, |
| expected_count.count); |
| } |
| |
| struct { |
| const char* name; |
| const base::HistogramBase::Sample32 latency_ms; |
| } expected_latencies[] = { |
| {"EventLatency.TouchPressed.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.TouchMoved.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.TouchMoved.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[0]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[1]).InMicroseconds())}, |
| {"EventLatency.TotalLatency", |
| static_cast<base::HistogramBase::Sample32>( |
| (presentation_time - event_times[2]).InMicroseconds())}, |
| }; |
| for (const auto& expected_latency : expected_latencies) { |
| histogram_tester.ExpectBucketCount(expected_latency.name, |
| expected_latency.latency_ms, 1); |
| } |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| NewMainUpdateIsNotPartialUpdate) { |
| // Start a frame with main-thread update. Submit the frame (and present) |
| // before the main-thread responds. This creates two reporters: R1C and R1M |
| // (R1C for the submitted frame with updates from compositor-thread, and R1M |
| // for the pending main-thread frame). |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, {}); |
| viz::FrameTimingDetails details = {}; |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(1u, details); |
| |
| // The main-thread responds now, triggering a commit and activation. |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| |
| const auto previous_id = current_id_; |
| |
| // Start a new frame with main-thread update. Submit the frame (and present) |
| // before the main-thread responds. This also again creates two reporters: R2C |
| // and R2M. |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info_main = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info_main, current_id_, |
| previous_id); |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(1u, details); |
| |
| // In total, two frames have been completed: R1C, and R1M. |
| // R2C has been presented, but it is blocked on R2M to know whether R2C |
| // contains partial update, or complete updates. So it is kept alive. |
| EXPECT_EQ(2u, frame_sorter_.total_frames()); |
| EXPECT_EQ(1u, frame_sorter_.total_partial()); |
| EXPECT_EQ(1u, reporting_controller_.GetBlockingReportersCount()); |
| EXPECT_EQ(1u, reporting_controller_.GetBlockedReportersCount()); |
| |
| reporting_controller_.ResetReporters(); |
| reporting_controller_.ClearFrameSequenceTrackerCollection(); |
| reporting_controller_.SetFrameSorter(nullptr); |
| } |
| |
| // Verifies that when a dependent frame is submitted to Viz, but not presented |
| // (hence dropped), should have its reporter immediately terminated and not |
| // adopted by the decider reporter. |
| TEST_F(CompositorFrameReportingControllerTest, |
| DependentDroppedFrameTerminatesReporterImmediately) { |
| // Start a frame with main-thread update and let it get stuck in main-thread. |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Start another frame that has impl-thread update and submit and present it |
| // successfully. The reporter for this frame should become dependent of the |
| // main reporter and adopted by it. |
| SimulateBeginImplFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, {}); |
| |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(1u, details_1); |
| |
| // There should be 1 blocking reporter, 1 blocked reporter, and 1 adopted |
| // reporter. |
| EXPECT_EQ(1u, reporting_controller_.GetBlockingReportersCount()); |
| EXPECT_EQ(1u, reporting_controller_.GetBlockedReportersCount()); |
| EXPECT_EQ(1u, reporting_controller_.GetAdoptedReportersCount()); |
| |
| // At this point no frame has been completed, yet. |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Start yet another frame that has impl-thread update and submit it, but with |
| // failed presentation. The reporter for this frame should become dependent of |
| // the main reporter, but should terminated immediately upon presentation |
| // failure, hence not adopted by the main reporter. |
| SimulateBeginImplFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info2 = {2u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, {}); |
| |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| details_2.presentation_feedback.flags |= gfx::PresentationFeedback::kFailure; |
| reporting_controller_.DidPresentCompositorFrame(2u, details_2); |
| |
| // There should be still 1 blocking reporter, but 2 blocked reporters. There |
| // should also be only 1 adopted reporter as the new reporter should not be |
| // adopted. |
| EXPECT_EQ(1u, reporting_controller_.GetBlockingReportersCount()); |
| EXPECT_EQ(2u, reporting_controller_.GetBlockedReportersCount()); |
| EXPECT_EQ(1u, reporting_controller_.GetAdoptedReportersCount()); |
| |
| // At this point 1 frame has been completed and it's a dropped frame. |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(1u, frame_sorter_.total_dropped()); |
| |
| reporting_controller_.ResetReporters(); |
| reporting_controller_.ClearFrameSequenceTrackerCollection(); |
| reporting_controller_.SetFrameSorter(nullptr); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| SkippedFramesFromDisplayCompositorAreDropped) { |
| // Submit and present two compositor frames. |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(2u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Now skip over a few frames, and submit + present another frame. |
| const uint32_t kSkipFrames = 5; |
| for (uint32_t i = 0; i < kSkipFrames; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(3u + kSkipFrames, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kSkipFrames, frame_sorter_.total_dropped()); |
| |
| // Stop requesting frames, skip over a few frames, and submit + present |
| // another frame. There should no new dropped frames. |
| frame_sorter_.Reset(/*reset_fcp=*/true); |
| reporting_controller_.OnStoppedRequestingBeginFrames(); |
| for (uint32_t i = 0; i < kSkipFrames; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| reporting_controller_.ResetReporters(); |
| reporting_controller_.ClearFrameSequenceTrackerCollection(); |
| reporting_controller_.SetFrameSorter(nullptr); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| SkippedFramesFromDisplayCompositorAreDroppedUpToLimit) { |
| // Submit and present two compositor frames. |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(2u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Now skip over a 101 frames (It should be ignored as it more than 100) |
| // and submit + present another frame. |
| const uint32_t kSkipFrames = 101; |
| const uint32_t kSkipFramesActual = 0; |
| for (uint32_t i = 0; i < kSkipFrames; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(3u + kSkipFramesActual, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kSkipFramesActual, frame_sorter_.total_dropped()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| CompositorFrameBlockedOnMainFrameWithNoDamage) { |
| viz::BeginFrameId current_id_1(1, 1); |
| viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1); |
| |
| viz::BeginFrameId current_id_2(1, 2); |
| viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2); |
| |
| viz::BeginFrameId current_id_3(1, 3); |
| viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3); |
| |
| viz::BeginFrameId current_id_4(1, 4); |
| viz::BeginFrameArgs args_4 = SimulateBeginFrameArgs(current_id_4); |
| |
| reporting_controller_.WillBeginImplFrame(args_1, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_1); |
| reporting_controller_.OnFinishImplFrame(current_id_1, |
| /*waiting_for_main=*/true); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| reporting_controller_.DidNotProduceFrame(args_1.frame_id, |
| FrameSkippedReason::kWaitingOnMain); |
| |
| reporting_controller_.WillBeginImplFrame(args_2, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(args_2.frame_id, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_2.frame_id, |
| FrameSkippedReason::kWaitingOnMain); |
| |
| reporting_controller_.WillBeginImplFrame(args_3, |
| /*will_throttle_main=*/false); |
| reporting_controller_.OnFinishImplFrame(args_3.frame_id, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(args_3.frame_id, |
| FrameSkippedReason::kWaitingOnMain); |
| |
| EXPECT_EQ(1u, reporting_controller_.GetBlockingReportersCount()); |
| EXPECT_EQ(3u, reporting_controller_.GetBlockedReportersCount()); |
| |
| // All frames are waiting for the main frame |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| |
| reporting_controller_.BeginMainFrameAborted( |
| args_1.frame_id, CommitEarlyOutReason::kFinishedNoUpdates); |
| reporting_controller_.DidNotProduceFrame(args_1.frame_id, |
| FrameSkippedReason::kNoDamage); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // New reporters replace older reporters |
| reporting_controller_.WillBeginImplFrame(args_4, |
| /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args_4); |
| |
| EXPECT_EQ(4u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| SkippedFramesFromDisplayCompositorHaveSmoothThread) { |
| auto thread_type_compositor = FrameInfo::SmoothThread::kSmoothCompositor; |
| tracker_collection_.StartSequence( |
| FrameSequenceTrackerType::kCompositorAnimation); |
| EXPECT_EQ(tracker_collection_.GetSmoothThread(), thread_type_compositor); |
| frame_sorter_.OnFirstContentfulPaintReceived(); |
| |
| // Submit and present two compositor frames. |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(2u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Now skip over a few frames, and submit + present another frame. |
| const uint32_t kSkipFrames_1 = 5; |
| for (uint32_t i = 0; i < kSkipFrames_1; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(3u + kSkipFrames_1, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kSkipFrames_1, frame_sorter_.total_dropped()); |
| |
| // Now skip over a few frames which are not affecting smoothness. |
| tracker_collection_.StopSequence( |
| FrameSequenceTrackerType::kCompositorAnimation); |
| EXPECT_EQ(tracker_collection_.GetSmoothThread(), |
| FrameInfo::SmoothThread::kSmoothNone); |
| const uint32_t kSkipFrames_2 = 7; |
| for (uint32_t i = 0; i < kSkipFrames_2; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); // Present another frame. |
| EXPECT_EQ(4u + kSkipFrames_1 + kSkipFrames_2, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kSkipFrames_1 + kSkipFrames_2, frame_sorter_.total_dropped()); |
| |
| // Now skip over a few frames more frames which are affecting smoothness. |
| tracker_collection_.StartSequence( |
| FrameSequenceTrackerType::kCompositorAnimation); |
| EXPECT_EQ(tracker_collection_.GetSmoothThread(), thread_type_compositor); |
| const uint32_t kSkipFrames_3 = 10; |
| for (uint32_t i = 0; i < kSkipFrames_3; ++i) |
| IncrementCurrentId(); |
| SimulatePresentCompositorFrame(); // Present another frame. |
| EXPECT_EQ(5u + kSkipFrames_1 + kSkipFrames_2 + kSkipFrames_3, |
| frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kSkipFrames_1 + kSkipFrames_2 + kSkipFrames_3, |
| frame_sorter_.total_dropped()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| SkippedFramesFromClientRequestedThrottlingAreDropped) { |
| // Submit and present two compositor frames. |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(1u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(2u, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Now skip over a few frames, and submit + present another frame. |
| const uint32_t kTotalFrames = 5; |
| const uint64_t kThrottledFrames = 4; |
| for (uint32_t i = 0; i < kTotalFrames; ++i) |
| IncrementCurrentId(); |
| args_.frames_throttled_since_last = kThrottledFrames; |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(3u + kTotalFrames - kThrottledFrames, frame_sorter_.total_frames()); |
| EXPECT_EQ(0u, frame_sorter_.total_partial()); |
| EXPECT_EQ(kTotalFrames - kThrottledFrames, frame_sorter_.total_dropped()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| DroppedFrameCountOnMainFrameAbort) { |
| // Start a few begin-main-frames, but abort the main-frames due to no damage. |
| for (int i = 0; i < 5; ++i) { |
| SimulateBeginImplFrame(); |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_, CommitEarlyOutReason::kFinishedNoUpdates); |
| } |
| EXPECT_EQ(0u, frame_sorter_.total_dropped()); |
| |
| // Start a few begin-main-frames, but abort the main-frames due to no damage. |
| for (int i = 0; i < 5; ++i) { |
| SimulateBeginImplFrame(); |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.BeginMainFrameAborted( |
| current_id_, CommitEarlyOutReason::kAbortedDeferredCommit); |
| SimulateSubmitCompositorFrame({}); |
| } |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(5u, frame_sorter_.total_dropped()); |
| } |
| |
| // Verifies that presentation feedbacks that arrive out of order are handled |
| // properly. See crbug.com/1195105 for more details. |
| TEST_F(CompositorFrameReportingControllerTest, |
| HandleOutOfOrderPresentationFeedback) { |
| // Submit three compositor frames without sending back their presentation |
| // feedbacks. |
| SimulateSubmitCompositorFrame({}); |
| |
| SimulateSubmitCompositorFrame({}); |
| const uint32_t frame_token_2 = *current_token_; |
| |
| SimulateSubmitCompositorFrame({}); |
| const uint32_t frame_token_3 = *current_token_; |
| |
| // Send a failed presentation feedback for frame 2. This should only drop |
| // frame 2 and leave frame 1 in the queue. |
| viz::FrameTimingDetails details_2; |
| details_2.presentation_feedback = {AdvanceNowByMs(10), base::TimeDelta(), |
| gfx::PresentationFeedback::kFailure}; |
| reporting_controller_.DidPresentCompositorFrame(frame_token_2, details_2); |
| DCHECK_EQ(1u, frame_sorter_.total_frames()); |
| DCHECK_EQ(1u, frame_sorter_.total_dropped()); |
| |
| // Send a successful presentation feedback for frame 3. This should drop frame |
| // 1. |
| viz::FrameTimingDetails details_3; |
| details_3.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(frame_token_3, details_3); |
| DCHECK_EQ(3u, frame_sorter_.total_frames()); |
| DCHECK_EQ(2u, frame_sorter_.total_dropped()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| NewMainThreadUpdateNotReportedAsDropped) { |
| auto thread_type_main = FrameInfo::SmoothThread::kSmoothMain; |
| tracker_collection_.StartSequence( |
| FrameSequenceTrackerType::kMainThreadAnimation); |
| EXPECT_EQ(tracker_collection_.GetSmoothThread(), thread_type_main); |
| |
| frame_sorter_.OnFirstContentfulPaintReceived(); |
| |
| SimulateBeginMainFrame(); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SubmitInfo submit_info = {1u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, {}); |
| viz::FrameTimingDetails details = {}; |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(1u, details); |
| // Starts a new frame and submit it prior to commit |
| |
| SimulateCommit(nullptr); |
| |
| const auto previous_id = current_id_; |
| |
| SimulateBeginMainFrame(); |
| DCHECK_NE(previous_id, current_id_); |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Starts a new frame and submit it prior to its commit, but the older frame |
| // has new updates which would be activated and submitted now. |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| |
| SubmitInfo submit_info2 = {2u, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, |
| previous_id); |
| details.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(2u, details); |
| |
| SimulateCommit(nullptr); |
| SimulatePresentCompositorFrame(); |
| |
| // There are two frames with partial updates |
| EXPECT_EQ(2u, frame_sorter_.total_partial()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, |
| NoUpdateCompositorWithJankyMain) { |
| frame_sorter_.OnFirstContentfulPaintReceived(); |
| |
| // Start a new frame and take it all the way to start the frame on the main |
| // thread (i.e. 'begin main frame'). |
| SimulateBeginMainFrame(); |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| |
| // Terminate the frame without submitting a frame. |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| reporting_controller_.DidNotProduceFrame(current_id_, |
| FrameSkippedReason::kWaitingOnMain); |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| |
| // Main thread responds. |
| SimulateActivate(); |
| EXPECT_EQ(1, reporting_controller_.ActiveReporters()); |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| |
| // Start and submit a second frame. |
| SimulateBeginImplFrame(); |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| EXPECT_EQ(0u, frame_sorter_.total_frames()); |
| |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SimulatePresentCompositorFrame(); |
| EXPECT_EQ(3u, frame_sorter_.total_frames()); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, MainFrameBeforeCommit) { |
| viz::BeginFrameArgs args1 = SimulateBeginFrameArgs({1, 1}); |
| viz::BeginFrameArgs args2 = SimulateBeginFrameArgs({1, 2}); |
| viz::BeginFrameArgs args3 = SimulateBeginFrameArgs({1, 3}); |
| viz::BeginFrameArgs args4 = SimulateBeginFrameArgs({1, 4}); |
| |
| // Frame 1 |
| reporting_controller_.WillBeginImplFrame(args1, /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args1); |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| // Frame 1 is ready to commit, so we can pipeline frame 2. |
| reporting_controller_.WillBeginImplFrame(args2, /*will_throttle_main=*/false); |
| reporting_controller_.WillBeginMainFrame(args2); |
| EXPECT_EQ(2, reporting_controller_.ActiveReporters()); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kBeginMainFrame)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kReadyToCommit)); |
| |
| // Commit frame 1 |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| // Frame 2 ready to commit |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillBeginImplFrame(args3, /*will_throttle_main=*/false); |
| EXPECT_EQ(3, reporting_controller_.ActiveReporters()); |
| // Pipeline frame 3 |
| reporting_controller_.WillBeginMainFrame(args3); |
| EXPECT_EQ(3, reporting_controller_.ActiveReporters()); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kBeginMainFrame)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kReadyToCommit)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kCommit)); |
| |
| // Activate frame 1 |
| reporting_controller_.WillActivate(); |
| reporting_controller_.DidActivate(); |
| // Commit frame 2 |
| reporting_controller_.WillCommit(); |
| reporting_controller_.DidCommit(); |
| // Frame 3 ready to commit |
| reporting_controller_.NotifyReadyToCommit(nullptr); |
| reporting_controller_.WillBeginImplFrame(args4, /*will_throttle_main=*/false); |
| EXPECT_EQ(4, reporting_controller_.ActiveReporters()); |
| // Pipeline frame 4 |
| reporting_controller_.WillBeginMainFrame(args4); |
| EXPECT_EQ(4, reporting_controller_.ActiveReporters()); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kBeginMainFrame)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kReadyToCommit)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kCommit)); |
| EXPECT_TRUE(reporting_controller_.HasReporterAt( |
| CompositorFrameReportingController::PipelineStage::kActivate)); |
| } |
| |
| // Glossary of acronyms used in the tests below. |
| // AMF - Activate Main Frame |
| // AbMF - AbortMainFrame |
| // BF - Begin Impl Frame |
| // BMF - Begin Main Frame |
| // CMF - Commit Main Frame |
| // PF - PresentFrame |
| // SF - Submit Compositor Frame |
| // |
| // This test verifies a compositor scroll scenario where the reporter |
| // termination is not in order, but we still expect the scroll jank tracker to |
| // receive the presentation data in order since it gets notified when controller |
| // receives DidPresentCompositorFrame. |
| // |
| // | R1main | |
| // | R1impl | R2impl | R3impl | |
| // | R2main | (aborted on main) |
| // | R3main | |
| // |
| // The order of events (using the glossary above) is: |
| // BF1->BMF1->SF1->PF1->BF2->CMF1->BMF2->SF2->AMF1->AbMF2-> |
| // BF3->BMF3->PF2->SF(3+1)->PF(3+1) |
| TEST_F(CompositorFrameReportingControllerTest, |
| ScrollJankMetricsPresentationOrderAbortedMain) { |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| |
| std::unique_ptr<EventMetrics> metrics_3 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| |
| SimulateBeginImplFrame(); // BF1 |
| viz::BeginFrameId bf1_id = current_id_; |
| SimulateBeginMainFrame(); // BMF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update with update from R1impl. |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_1), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| {}); // SF1 |
| |
| // Present the frame with R1impl. |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| viz::BeginFrameId bf2_id = current_id_; |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SimulateCommit(nullptr); // CMF1 |
| SimulateBeginMainFrame(); // BMF2 |
| |
| // Submit partial update containing R2impl, R1main update is only committed |
| // yet not activated, so it doesn't go into the frame. |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| ++current_token_; |
| SubmitInfo submit_info2 = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_2), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, |
| {}); // SF2 |
| SimulateActivate(); // AMF1 |
| |
| // R2main is aborted with no updates desired. |
| reporting_controller_.BeginMainFrameAborted( |
| bf2_id, CommitEarlyOutReason::kFinishedNoUpdates); // AbMF2 |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| // Begin main frame 3, this replaces the R2main in controller and terminates |
| // the reporter. So R2impl won't get adopted by R2main. |
| SimulateBeginMainFrame(); // BMF3 |
| |
| // Present the frame containing R2impl. |
| // R2impl gets terminated here immediately and reports its metrics to scroll |
| // jank tracker. |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF2 |
| |
| // Submit frame containing R1main and R3impl. |
| ++current_token_; |
| SubmitInfo submit_info3 = {*current_token_, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_, |
| bf1_id); // SF(3+1) |
| |
| // Present frame containing R1main and R3impl. |
| // This is where R1impl will be terminated as well, since it got adopted by |
| // R1main. |
| viz::FrameTimingDetails details_3 = {}; |
| details_3.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_3); // PF(3+1) |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| std::string query = |
| R"( |
| SELECT count(*) as cnt from slice |
| where name = 'OutOfOrderTerminatedFrame' |
| )"; |
| auto result = ttp.RunQuery(query); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| // Even though R2impl gets terminated before R1impl, but we still expect the |
| // scroll jank metrics to be reported in order. |
| EXPECT_THAT(result.value(), |
| ::testing::ElementsAre(std::vector<std::string>{"cnt"}, |
| std::vector<std::string>{"0"})); |
| } |
| |
| // This test verifies a main thread scroll scenario where a frame with |
| // compositor only update gets dropped, and the events should end up in the long |
| // running main reporter. So we expect the scroll jank dropped frame tracker |
| // receives data only for the one presented frame corresponding to the long |
| // running main thread update. |
| // |
| // | R1main | |
| // | R1impl | R2impl | R3impl | |
| // |
| // The order of events (using the glossary above) is: |
| // BF1->BMF1->SF1->PF1->BF2->SF2->PF2(dropped)->AMF1->BF3->SF(3+1)->PF(3+1) |
| TEST_F(CompositorFrameReportingControllerTest, |
| ScrollJankMetricsPresentationOrderDroppedPartialOnMainScroll) { |
| base::HistogramTester histogram_tester; |
| |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| metrics_1->set_requires_main_thread_update(); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| metrics_2->set_requires_main_thread_update(); |
| |
| SimulateBeginImplFrame(); // BF1 |
| viz::BeginFrameId bf1_id = current_id_; |
| SimulateBeginMainFrame(); // BMF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update including only main update from R1impl. |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_1), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| {}); // SF1 |
| |
| // Present the partial update. |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update including only main update from R2impl. |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| ++current_token_; |
| SubmitInfo submit_info2 = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_2), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, |
| {}); // SF2 |
| |
| // The frame containing R2impl update got dropped. |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| details_2.presentation_feedback.flags |= gfx::PresentationFeedback::kFailure; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF2 |
| |
| // Main thread commits and the tree is activated. |
| SimulateCommit(nullptr); |
| SimulateActivate(); // AMF1 |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit the frame containing updates from R1main and R3impl. |
| ++current_token_; |
| SubmitInfo submit_info3 = {*current_token_, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_, |
| bf1_id); // SF(3+1) |
| |
| // Present frame containing update from R1main and R3impl. |
| viz::FrameTimingDetails details_3 = {}; |
| details_3.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_3); // PF(3+1) |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| std::string query = |
| R"( |
| SELECT count(*) as cnt from slice |
| where name = 'OutOfOrderTerminatedFrame' |
| )"; |
| auto result = ttp.RunQuery(query); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| // R1main should ideally have gotten both the events i.e. from R1impl and |
| // R2impl, so we wouldn't expect anything to be out of order with just 1 |
| // reporter having both inputs. |
| EXPECT_THAT(result.value(), |
| ::testing::ElementsAre(std::vector<std::string>{"cnt"}, |
| std::vector<std::string>{"0"})); |
| |
| histogram_tester.ExpectTotalCount("Event.ScrollJank.MissedVsyncs.PerFrame", |
| 1); |
| } |
| |
| // This test verifies events from a dropped impl reporter gets added to |
| // corresponding impl reporter only. |
| // |
| // | R1main | |
| // | R1impl | R2impl | |
| // |
| // The order of events (using the glossary above) is: |
| // BF1->BMF1->SF1->PF1(dropped)->BF2->AMF1->SF(2+1)->PF(2+1) |
| TEST_F(CompositorFrameReportingControllerTest, |
| ScrollJankMetricsPresentationOrderDroppedPartialOnImplScroll) { |
| base::HistogramTester histogram_tester; |
| |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| |
| SimulateBeginImplFrame(); // BF1 |
| viz::BeginFrameId bf1_id = current_id_; |
| SimulateBeginMainFrame(); // BMF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update including only main update from R1impl. |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_1), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| {}); // SF1 |
| |
| // Frame 1 is dropped. |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| details_1.presentation_feedback.flags |= gfx::PresentationFeedback::kFailure; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1(dropped) |
| |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SimulateCommit(nullptr); |
| SimulateActivate(); // AMF1 |
| |
| // Submit a partial update including only main update from R2impl. |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| ++current_token_; |
| SubmitInfo submit_info2 = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info2.events_metrics = {{}, std::move(metrics_list_2), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, |
| bf1_id); // SF(2+1) |
| |
| // The frame containing R2impl and R1main is presented. |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF(2+1) |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| std::string query = |
| R"( |
| SELECT count(*) as cnt from slice |
| where name = 'OutOfOrderTerminatedFrame' |
| )"; |
| auto result = ttp.RunQuery(query); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| // R2impl should get the events from R1impl so we wouldn't expect anything to |
| // be out of order with just 1 reporter having both inputs. |
| EXPECT_THAT(result.value(), |
| ::testing::ElementsAre(std::vector<std::string>{"cnt"}, |
| std::vector<std::string>{"0"})); |
| |
| histogram_tester.ExpectTotalCount("Event.ScrollJank.MissedVsyncs.PerFrame", |
| 1); |
| } |
| |
| // This test verifies the events from dropped frames doesn't get passed to |
| // adopter if the impl only update was successful. As a result we expect only |
| // two frames to report scroll jank metrics i.e. the frames corresponding to |
| // R3impl and R4impl+R2main. |
| // |
| // | R1main | |
| // | R1impl | R2impl | R3impl | R4impl | |
| // | R2main | |
| // |
| // The order of events (using the glossary above) is: |
| // BF1->BMF1->SF1->PF1->AMF1->BF2->BMF2->SF(2+1)->PF(2+1)(dropped)-> |
| // BF3->SF3->PF3->AMF2->BF4->SF(4+2)->PF(4+2) |
| TEST_F(CompositorFrameReportingControllerTest, |
| ScrollJankMetricsPresentationOrderReceivedDroppedEventsAreNotPassed) { |
| base::HistogramTester histogram_tester; |
| |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| metrics_1->set_requires_main_thread_update(); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| metrics_2->set_requires_main_thread_update(); |
| |
| std::unique_ptr<EventMetrics> metrics_3 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| metrics_3->set_requires_main_thread_update(); |
| |
| SimulateBeginImplFrame(); // BF1 |
| viz::BeginFrameId bf1_id = current_id_; |
| SimulateBeginMainFrame(); // BMF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit a partial update containing R1impl. |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| ++current_token_; |
| SubmitInfo submit_info = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info.events_metrics = {{}, std::move(metrics_list_1), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info, current_id_, |
| {}); // SF1 |
| |
| // Present frame containing update from R1impl. |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| // Commit and activate main update from R1main. |
| SimulateCommit(nullptr); |
| SimulateActivate(); // AMF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| viz::BeginFrameId bf2_id = current_id_; |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| SimulateBeginMainFrame(); // BMF2 |
| |
| // Submit frame containing update from R1main and R2impl. |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| ++current_token_; |
| SubmitInfo submit_info2 = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info2.events_metrics = {{}, std::move(metrics_list_2), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info2, current_id_, |
| bf1_id); // SF(2+1) |
| |
| // The frame containing R1main and R2impl was dropped. |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| details_2.presentation_feedback.flags |= gfx::PresentationFeedback::kFailure; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF(2+1) |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit partial update containing R3impl. |
| EventMetrics::List metrics_list_3; |
| metrics_list_3.push_back(std::move(metrics_3)); |
| ++current_token_; |
| SubmitInfo submit_info3 = {*current_token_, AdvanceNowByMs(10)}; |
| submit_info3.events_metrics = {{}, std::move(metrics_list_3), {}}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info3, current_id_, |
| bf1_id); // SF3 |
| |
| viz::FrameTimingDetails details_3 = {}; |
| details_3.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_3); // PF3 |
| |
| // Commit and activate main update from R2main. |
| SimulateCommit(nullptr); |
| SimulateActivate(); // AMF2 |
| |
| SimulateBeginImplFrame(); // BF4 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| |
| // Submit frame containing update from R2main and R4impl. |
| ++current_token_; |
| SubmitInfo submit_info4 = {*current_token_, AdvanceNowByMs(10)}; |
| reporting_controller_.DidSubmitCompositorFrame(submit_info4, current_id_, |
| bf2_id); // SF(4+2) |
| |
| // Present frame containing R2main and R4impl. |
| viz::FrameTimingDetails details_4 = {}; |
| details_4.presentation_feedback.timestamp = AdvanceNowByMs(10); |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_4); // PF(4+2) |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| std::string query = |
| R"( |
| SELECT count(*) as cnt from slice |
| where name = 'OutOfOrderTerminatedFrame' |
| )"; |
| auto result = ttp.RunQuery(query); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| EXPECT_THAT(result.value(), |
| ::testing::ElementsAre(std::vector<std::string>{"cnt"}, |
| std::vector<std::string>{"0"})); |
| |
| // Expect reporters R3impl, R2main to report data to scroll jank tracker. |
| // R3impl - The events it received from previously dropped frames. |
| // R2main - The events associated with the reporter itself. |
| histogram_tester.ExpectTotalCount("Event.ScrollJank.MissedVsyncs.PerFrame", |
| 2); |
| } |
| |
| TEST_F(CompositorFrameReportingControllerTest, EmitsEventLatencyId) { |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, |
| base::IdType64<class ui::LatencyInfo>(14)); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateEventMetrics( |
| ui::EventType::kTouchPressed, base::IdType64<class ui::LatencyInfo>(15)); |
| |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| metrics_list_1.push_back(std::move(metrics_2)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_1), {}}); |
| SimulatePresentCompositorFrame(); |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| std::string query = |
| R"( |
| SELECT count(*) AS cnt |
| FROM slice |
| WHERE name = 'EventLatency' |
| AND (EXTRACT_ARG(arg_set_id, 'event_latency.event_latency_id') = 14 |
| OR EXTRACT_ARG(arg_set_id, 'event_latency.event_latency_id') = 15) |
| )"; |
| auto result = ttp.RunQuery(query); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| EXPECT_THAT(result.value(), |
| ::testing::ElementsAre(std::vector<std::string>{"cnt"}, |
| std::vector<std::string>{"2"})); |
| } |
| |
| constexpr const char kScrollJankMetricArgsQuery[] = |
| R"( |
| SELECT |
| EXTRACT_ARG(arg_set_id, 'event_latency.is_janky_scrolled_frame') |
| AS is_janky, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.is_janky' |
| ) AS is_janky_v4, |
| ( |
| -- Concatenate the `missed_vsyncs_per_jank_reason` repeated field into a |
| -- single string. For example, the following value: |
| -- |
| -- { jank_reason: REASON_A, missed_vsyncs: 1 } |
| -- { jank_reason: REASON_B, missed_vsyncs: 2 } |
| -- { jank_reason: REASON_C, missed_vsyncs: 3 } |
| -- |
| -- is converted to 'REASON_A(1),REASON_B(2),REASON_C(3)'. |
| SELECT |
| GROUP_CONCAT( |
| FORMAT('%s(%d)', jank_reason, missed_vsyncs), |
| ',' |
| ORDER BY jank_reason ASC |
| ) |
| FROM |
| ( |
| SELECT |
| args.string_value AS jank_reason, |
| SUBSTRING(args.key, 1, LENGTH(args.key) - LENGTH('.jank_reason')) |
| AS key_prefix |
| FROM args |
| WHERE |
| args.arg_set_id = slice.arg_set_id |
| AND args.flat_key = |
| 'event_latency.scroll_jank_v4.' |
| || 'missed_vsyncs_per_jank_reason.jank_reason' |
| ) |
| JOIN |
| ( |
| SELECT |
| args.int_value AS missed_vsyncs, |
| SUBSTRING( |
| args.key, |
| 1, |
| LENGTH(args.key) - LENGTH('.missed_vsyncs') |
| ) AS key_prefix |
| FROM args |
| WHERE |
| args.arg_set_id = slice.arg_set_id |
| AND args.flat_key = |
| 'event_latency.scroll_jank_v4.' |
| || 'missed_vsyncs_per_jank_reason.missed_vsyncs' |
| ) |
| -- Join the corresponding `jank_reason` and `missed_vsyncs` via |
| -- their shared |
| -- 'event_latency.scroll_jank_v4. |
| -- missed_vsyncs_per_jank_reason[INDEX]' |
| -- key prefix. |
| USING(key_prefix) |
| ) AS jank_reasons, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.abs_total_raw_delta_pixels' |
| ) AS abs_total_raw_delta_pixels, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.max_abs_inertial_raw_delta_pixels' |
| ) AS max_abs_inertial_raw_delta_pixels, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.vsyncs_since_previous_frame' |
| ) AS vsyncs_since_previous_frame, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.running_delivery_cutoff_us' |
| ) AS running_delivery_cutoff_us, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.adjusted_delivery_cutoff_us' |
| ) AS adjusted_delivery_cutoff_us, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.current_delivery_cutoff_us' |
| ) AS current_delivery_cutoff_us, |
| EXTRACT_ARG( |
| arg_set_id, |
| 'event_latency.scroll_jank_v4.is_damaging_frame' |
| ) AS is_damaging_frame |
| FROM slice |
| WHERE name = 'EventLatency' |
| ORDER BY ts ASC; |
| )"; |
| |
| /* |
| Test if we emit scroll-jank-metric-related arguments. |
| vsync | | | | | | | | | |
| input GSU1 GSU2 GSU3 non-GSU |
| | | | | |
| F1: |-----------------------| |
| F2: |-----------------------------| |
| F3: |-----------------------------| |
| F4: |-----------------------------| |
| F1 and F3 should have is_janky_scrolled_frame set to false while F2 should have |
| it set to true and F4 should not have a value for the argument. |
| */ |
| TEST_F(CompositorFrameReportingControllerTest, ScrollJankMetricArgs) { |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| base::TimeTicks event1_generation_ts = metrics_1->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| base::TimeTicks event2_generation_ts = metrics_2->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> metrics_3 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/true, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| base::TimeTicks event3_generation_ts = metrics_3->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> non_scroll_event = |
| CreateEventMetrics(ui::EventType::kTouchPressed, std::nullopt); |
| |
| base::TimeDelta vsync_interval = event2_generation_ts - event1_generation_ts; |
| args_.interval = vsync_interval; |
| |
| SimulateBeginImplFrame(); // BF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_1), {}}); |
| |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = event3_generation_ts; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_2), {}}); |
| |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = |
| details_1.presentation_feedback.timestamp + 2 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF2 |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_3; |
| metrics_list_3.push_back(std::move(metrics_3)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_3), {}}); |
| |
| viz::FrameTimingDetails details_3 = {}; |
| details_3.presentation_feedback.timestamp = |
| details_2.presentation_feedback.timestamp + vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_3); // PF3 |
| |
| SimulateBeginImplFrame(); // BF4 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_4; |
| metrics_list_4.push_back(std::move(non_scroll_event)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_4), {}}); |
| |
| viz::FrameTimingDetails details_4 = {}; |
| details_4.presentation_feedback.timestamp = |
| details_3.presentation_feedback.timestamp + vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_4); // PF4 |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| auto result = ttp.RunQuery(kScrollJankMetricArgsQuery); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| |
| EXPECT_THAT( |
| result.value(), |
| ::testing::ElementsAre( |
| std::vector<std::string>{ |
| "is_janky", "is_janky_v4", "jank_reasons", |
| "abs_total_raw_delta_pixels", "max_abs_inertial_raw_delta_pixels", |
| "vsyncs_since_previous_frame", "running_delivery_cutoff_us", |
| "adjusted_delivery_cutoff_us", "current_delivery_cutoff_us", |
| "is_damaging_frame"}, |
| std::vector<std::string>{"0", "0", "[NULL]", "10", "0", "[NULL]", |
| "[NULL]", "[NULL]", "86000", "1"}, |
| std::vector<std::string>{ |
| "1", "1", |
| "MISSED_VSYNC_DUE_TO_DECELERATING_INPUT_FRAME_DELIVERY(1),MISSED_" |
| "VSYNC_DURING_FAST_SCROLL(1)", |
| "10", "0", "2", "86000", "84000", "129000", "1"}, |
| std::vector<std::string>{"0", "0", "[NULL]", "10", "10", "1", |
| "129000", "[NULL]", "129000", "1"}, |
| std::vector<std::string>{"[NULL]", "[NULL]", "[NULL]", "[NULL]", |
| "[NULL]", "[NULL]", "[NULL]", "[NULL]", |
| "[NULL]", "[NULL]"})); |
| } |
| |
| /* |
| Test if the new v4 metric logic identifies scroll jank in a scenario where a |
| frame is throttled. |
| vsync | | | | | |
| input GSU1 GSU2 GSU3 |
| | | | |
| F1: |---------------| |
| F2: |---------------x (throttled) |
| F3: |--------------| |
| The new v4 metric should identify scroll jank because F2 got dropped even though |
| there was consistent input for a frame to have been generated. |
| */ |
| TEST_F(CompositorFrameReportingControllerTest, JankyThrottledScrolledFrame) { |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| base::TimeTicks event1_generation_ts = metrics_1->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| base::TimeTicks event2_generation_ts = metrics_2->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> metrics_3 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| base::TimeTicks event3_generation_ts = metrics_3->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| base::TimeDelta vsync_interval = event2_generation_ts - event1_generation_ts; |
| args_.interval = vsync_interval; |
| |
| SimulateBeginImplFrame(); // BF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_1), {}}); |
| |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = event3_generation_ts; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| AdvanceNowByMs(10); |
| reporting_controller_.DidNotProduceFrame(current_id_, |
| FrameSkippedReason::kDrawThrottled); |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_3; |
| metrics_list_3.push_back(std::move(metrics_2)); |
| metrics_list_3.push_back(std::move(metrics_3)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_3), {}}); |
| |
| viz::FrameTimingDetails details_3 = {}; |
| details_3.presentation_feedback.timestamp = |
| details_1.presentation_feedback.timestamp + 2 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_3); // PF3 |
| |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| auto result = ttp.RunQuery(kScrollJankMetricArgsQuery); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| EXPECT_THAT( |
| result.value(), |
| ::testing::ElementsAre( |
| std::vector<std::string>{ |
| "is_janky", "is_janky_v4", "jank_reasons", |
| "abs_total_raw_delta_pixels", "max_abs_inertial_raw_delta_pixels", |
| "vsyncs_since_previous_frame", "running_delivery_cutoff_us", |
| "adjusted_delivery_cutoff_us", "current_delivery_cutoff_us", |
| "is_damaging_frame"}, |
| std::vector<std::string>{"0", "0", "[NULL]", "10", "0", "[NULL]", |
| "[NULL]", "[NULL]", "86000", "1"}, |
| std::vector<std::string>{ |
| "[NULL]", "1", |
| "MISSED_VSYNC_DUE_TO_DECELERATING_INPUT_FRAME_DELIVERY(1),MISSED_" |
| "VSYNC_DURING_FAST_SCROLL(1)", |
| "20", "0", "2", "86000", "84000", "86000", "1"}, |
| std::vector<std::string>{"0", "[NULL]", "[NULL]", "[NULL]", "[NULL]", |
| "[NULL]", "[NULL]", "[NULL]", "[NULL]", |
| "[NULL]"})); |
| } |
| |
| /* |
| Test that the controller emits both the v1 and v4 per-scroll jank metrics. It |
| should emit v1 metrics when it encounters the next first gesture scroll update |
| event. It should emit v4 metrics when it encounters a gestures scroll end event. |
| |
| vsync | | | | | | | |
| input GSU1 GSU2 GSE FGSU3 | |
| | | | | | |
| F1: |---------------| | | |
| F2: |---------------| | |
| F3: |---------------x (throttled) | |
| F4: | -------| | |
| F5: |-----------------------| |
| ^ ^ |
| | | |
| | v1 metrics emitted |
| v4 metrics emitted |
| */ |
| TEST_F(CompositorFrameReportingControllerTest, EmitsPerScrollJankMetrics) { |
| std::unique_ptr<EventMetrics> scroll_update1_metrics = |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| base::TimeTicks scroll_update1_generation_ts = |
| scroll_update1_metrics->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> scroll_update2_metrics = |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| base::TimeTicks scroll_update2_generation_ts = |
| scroll_update2_metrics->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> scroll_end_metrics = |
| CreateScrollEndEventMetrics(ui::ScrollInputType::kWheel, |
| /*is_inertial=*/false); |
| base::TimeTicks scroll_end_generation_ts = |
| scroll_end_metrics->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| std::unique_ptr<EventMetrics> scroll_update3_metrics = |
| CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| base::TimeTicks scroll_update3_generation_ts = |
| scroll_update3_metrics->GetDispatchStageTimestamp( |
| EventMetrics::DispatchStage::kGenerated); |
| |
| base::TimeDelta vsync_interval = |
| scroll_update2_generation_ts - scroll_update1_generation_ts; |
| args_.interval = vsync_interval; |
| |
| { |
| base::HistogramTester histogram_tester; |
| |
| SimulateBeginImplFrame(); // BF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(scroll_update1_metrics)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_1), {}}); |
| |
| viz::FrameTimingDetails details_1 = {}; |
| details_1.presentation_feedback.timestamp = |
| scroll_update1_generation_ts + 2 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_1); // PF1 |
| |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(scroll_update2_metrics)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_2), {}}); |
| |
| viz::FrameTimingDetails details_2 = {}; |
| details_2.presentation_feedback.timestamp = |
| scroll_update2_generation_ts + 2 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_2); // PF2 |
| |
| SimulateBeginImplFrame(); // BF3 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| AdvanceNowByMs(10); |
| reporting_controller_.DidNotProduceFrame( |
| current_id_, FrameSkippedReason::kDrawThrottled); |
| |
| SimulateBeginImplFrame(); // BF4 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_4; |
| metrics_list_4.push_back(std::move(scroll_end_metrics)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_4), {}}); |
| |
| viz::FrameTimingDetails details_4 = {}; |
| details_4.presentation_feedback.timestamp = |
| scroll_end_generation_ts + 3 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_4); // PF4 |
| |
| // The controller should emit v4 per-scroll metrics when it processes the |
| // end of the scroll (`scroll_end_metrics`). |
| histogram_tester.ExpectTotalCount( |
| "Event.ScrollJank.DelayedFramesPercentage.PerScroll", 0); |
| histogram_tester.ExpectTotalCount( |
| "Event.ScrollJank.DelayedFramesPercentage4.PerScroll", 1); |
| } |
| |
| { |
| base::HistogramTester histogram_tester; |
| |
| SimulateBeginImplFrame(); // BF5 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_5; |
| metrics_list_5.push_back(std::move(scroll_update3_metrics)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_5), {}}); |
| |
| viz::FrameTimingDetails details_5 = {}; |
| details_5.presentation_feedback.timestamp = |
| scroll_update3_generation_ts + 3 * vsync_interval; |
| reporting_controller_.DidPresentCompositorFrame(*current_token_, |
| details_5); // PF5 |
| |
| // The controller should emit v1 per-scroll metrics when it processes the |
| // first update of the next scroll (`scroll_update3_metrics`). |
| histogram_tester.ExpectTotalCount( |
| "Event.ScrollJank.DelayedFramesPercentage.PerScroll", 1); |
| histogram_tester.ExpectTotalCount( |
| "Event.ScrollJank.DelayedFramesPercentage4.PerScroll", 0); |
| } |
| } |
| |
| // A simple test that ensures the vsync_interval is copied onto the |
| // EventLatency. |
| TEST_F(CompositorFrameReportingControllerTest, VsyncIntervalArg) { |
| base::test::TestTraceProcessor ttp; |
| ttp.StartTrace("input"); |
| |
| std::unique_ptr<EventMetrics> metrics_1 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kStarted, std::nullopt); |
| |
| std::unique_ptr<EventMetrics> metrics_2 = CreateScrollUpdateEventMetrics( |
| ui::ScrollInputType::kWheel, /*is_inertial=*/false, |
| ScrollUpdateEventMetrics::ScrollUpdateType::kContinued, std::nullopt); |
| |
| std::unique_ptr<EventMetrics> non_scroll_event = |
| CreateEventMetrics(ui::EventType::kTouchPressed, std::nullopt); |
| |
| // First BeginFrame with a 32ms interval. |
| args_.interval = base::Milliseconds(32); |
| SimulateBeginImplFrame(); // BF1 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_1; |
| metrics_list_1.push_back(std::move(metrics_1)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_1), {}}); |
| |
| // Presentation of the first BeginFrame. |
| SimulatePresentCompositorFrame(); |
| |
| // Second BeginFrame with an 8ms interval. |
| args_.interval = base::Milliseconds(8); |
| SimulateBeginImplFrame(); // BF2 |
| reporting_controller_.OnFinishImplFrame(current_id_, |
| /*waiting_for_main=*/true); |
| EventMetrics::List metrics_list_2; |
| metrics_list_2.push_back(std::move(metrics_2)); |
| SimulateSubmitCompositorFrame({{}, std::move(metrics_list_2), {}}); |
| |
| // Presentation of the second BeginFrame. |
| SimulatePresentCompositorFrame(); |
| |
| // Query and ensure we see both intervals on different events. |
| absl::Status status = ttp.StopAndParseTrace(); |
| ASSERT_TRUE(status.ok()) << status.message(); |
| constexpr char kQuery[] = |
| R"( |
| SELECT |
| EXTRACT_ARG(slice.arg_set_id, 'event_latency.vsync_interval_ms') AS interval, COUNT(*) AS cnt |
| FROM slice |
| WHERE name = 'EventLatency' |
| GROUP BY 1 |
| ORDER BY 1 ASC |
| )"; |
| auto result = ttp.RunQuery(kQuery); |
| ASSERT_TRUE(result.has_value()) << result.error(); |
| EXPECT_THAT(result.value(), ::testing::ElementsAre( |
| std::vector<std::string>{"interval", "cnt"}, |
| std::vector<std::string>{"8", "1"}, |
| std::vector<std::string>{"32", "1"})); |
| } |
| |
| } // namespace |
| } // namespace cc |