1 // Copyright 2015 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include "cc/metrics/compositor_timing_history.h"
6
7 #include "base/logging.h"
8 #include "cc/debug/rendering_stats_instrumentation.h"
9 #include "cc/metrics/dropped_frame_counter.h"
10 #include "cc/test/fake_compositor_frame_reporting_controller.h"
11 #include "testing/gtest/include/gtest/gtest.h"
12
13 namespace cc {
14 namespace {
15
16 class CompositorTimingHistoryTest;
17
18 class TestCompositorTimingHistory : public CompositorTimingHistory {
19 public:
TestCompositorTimingHistory(CompositorTimingHistoryTest * test,RenderingStatsInstrumentation * rendering_stats,CompositorFrameReportingController * reporting_controller)20 TestCompositorTimingHistory(
21 CompositorTimingHistoryTest* test,
22 RenderingStatsInstrumentation* rendering_stats,
23 CompositorFrameReportingController* reporting_controller)
24 : CompositorTimingHistory(false,
25 RENDERER_UMA,
26 rendering_stats,
27 reporting_controller),
28 test_(test) {}
29
30 TestCompositorTimingHistory(const TestCompositorTimingHistory&) = delete;
31 TestCompositorTimingHistory& operator=(const TestCompositorTimingHistory&) =
32 delete;
33
34 protected:
35 base::TimeTicks Now() const override;
36
37 CompositorTimingHistoryTest* test_;
38 };
39
40 class CompositorTimingHistoryTest : public testing::Test {
41 public:
CompositorTimingHistoryTest()42 CompositorTimingHistoryTest()
43 : rendering_stats_(RenderingStatsInstrumentation::Create()),
44 reporting_controller_(
45 std::make_unique<FakeCompositorFrameReportingController>()),
46 timing_history_(this,
47 rendering_stats_.get(),
48 reporting_controller_.get()) {
49 AdvanceNowBy(base::TimeDelta::FromMilliseconds(1));
50 timing_history_.SetRecordingEnabled(true);
51 reporting_controller_->SetDroppedFrameCounter(&dropped_counter);
52 }
53
AdvanceNowBy(base::TimeDelta delta)54 void AdvanceNowBy(base::TimeDelta delta) { now_ += delta; }
55
Now()56 base::TimeTicks Now() { return now_; }
57
58 protected:
59 std::unique_ptr<RenderingStatsInstrumentation> rendering_stats_;
60 std::unique_ptr<CompositorFrameReportingController> reporting_controller_;
61 TestCompositorTimingHistory timing_history_;
62 base::TimeTicks now_;
63 uint64_t sequence_number = 0;
64 DroppedFrameCounter dropped_counter;
65
GetFakeBeginFrameArg(bool on_critical_path=true)66 viz::BeginFrameArgs GetFakeBeginFrameArg(bool on_critical_path = true) {
67 viz::BeginFrameArgs args = viz::BeginFrameArgs();
68 const uint64_t kSourceId = 1;
69 args.frame_id = {kSourceId, ++sequence_number};
70 args.frame_time = Now();
71 args.on_critical_path = on_critical_path;
72 return args;
73 }
74 };
75
Now() const76 base::TimeTicks TestCompositorTimingHistory::Now() const {
77 return test_->Now();
78 }
79
TEST_F(CompositorTimingHistoryTest,AllSequential_Commit)80 TEST_F(CompositorTimingHistoryTest, AllSequential_Commit) {
81 base::TimeDelta one_second = base::TimeDelta::FromSeconds(1);
82
83 // Critical BeginMainFrames are faster than non critical ones,
84 // as expected.
85 base::TimeDelta begin_main_frame_queue_duration =
86 base::TimeDelta::FromMilliseconds(1);
87 base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
88 base::TimeDelta::FromMilliseconds(1);
89 base::TimeDelta prepare_tiles_duration = base::TimeDelta::FromMilliseconds(2);
90 base::TimeDelta prepare_tiles_end_to_ready_to_activate_duration =
91 base::TimeDelta::FromMilliseconds(1);
92 base::TimeDelta commit_to_ready_to_activate_duration =
93 base::TimeDelta::FromMilliseconds(3);
94 base::TimeDelta commit_duration = base::TimeDelta::FromMilliseconds(1);
95 base::TimeDelta activate_duration = base::TimeDelta::FromMilliseconds(4);
96 base::TimeDelta draw_duration = base::TimeDelta::FromMilliseconds(5);
97
98 timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg());
99 AdvanceNowBy(begin_main_frame_queue_duration);
100 timing_history_.BeginMainFrameStarted(Now());
101 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
102 timing_history_.NotifyReadyToCommit(nullptr);
103 timing_history_.WillCommit();
104 AdvanceNowBy(commit_duration);
105 timing_history_.DidCommit();
106 timing_history_.WillPrepareTiles();
107 AdvanceNowBy(prepare_tiles_duration);
108 timing_history_.DidPrepareTiles();
109 AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
110 timing_history_.ReadyToActivate();
111 // Do not count idle time between notification and actual activation.
112 AdvanceNowBy(one_second);
113 timing_history_.WillActivate();
114 AdvanceNowBy(activate_duration);
115 timing_history_.DidActivate();
116 // Do not count idle time between activate and draw.
117 AdvanceNowBy(one_second);
118 timing_history_.WillDraw();
119 AdvanceNowBy(draw_duration);
120 timing_history_.DidDraw(true, false);
121
122 EXPECT_EQ(begin_main_frame_queue_duration,
123 timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
124 EXPECT_EQ(begin_main_frame_queue_duration,
125 timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
126
127 EXPECT_EQ(
128 begin_main_frame_start_to_ready_to_commit_duration,
129 timing_history_.BeginMainFrameStartToReadyToCommitDurationEstimate());
130 EXPECT_EQ(commit_duration, timing_history_.CommitDurationEstimate());
131 EXPECT_EQ(commit_to_ready_to_activate_duration,
132 timing_history_.CommitToReadyToActivateDurationEstimate());
133 EXPECT_EQ(prepare_tiles_duration,
134 timing_history_.PrepareTilesDurationEstimate());
135 EXPECT_EQ(activate_duration, timing_history_.ActivateDurationEstimate());
136 EXPECT_EQ(draw_duration, timing_history_.DrawDurationEstimate());
137 }
138
TEST_F(CompositorTimingHistoryTest,AllSequential_BeginMainFrameAborted)139 TEST_F(CompositorTimingHistoryTest, AllSequential_BeginMainFrameAborted) {
140 base::TimeDelta one_second = base::TimeDelta::FromSeconds(1);
141
142 base::TimeDelta begin_main_frame_queue_duration =
143 base::TimeDelta::FromMilliseconds(1);
144 base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
145 base::TimeDelta::FromMilliseconds(1);
146 base::TimeDelta prepare_tiles_duration = base::TimeDelta::FromMilliseconds(2);
147 base::TimeDelta prepare_tiles_end_to_ready_to_activate_duration =
148 base::TimeDelta::FromMilliseconds(1);
149 base::TimeDelta activate_duration = base::TimeDelta::FromMilliseconds(4);
150 base::TimeDelta draw_duration = base::TimeDelta::FromMilliseconds(5);
151
152 viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(false);
153 timing_history_.WillBeginMainFrame(args_);
154 AdvanceNowBy(begin_main_frame_queue_duration);
155 timing_history_.BeginMainFrameStarted(Now());
156 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
157 // BeginMainFrameAborted counts as a commit complete.
158 timing_history_.BeginMainFrameAborted(
159 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
160 timing_history_.WillPrepareTiles();
161 AdvanceNowBy(prepare_tiles_duration);
162 timing_history_.DidPrepareTiles();
163 AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
164 // Do not count idle time between notification and actual activation.
165 AdvanceNowBy(one_second);
166 timing_history_.WillActivate();
167 AdvanceNowBy(activate_duration);
168 timing_history_.DidActivate();
169 // Do not count idle time between activate and draw.
170 AdvanceNowBy(one_second);
171 timing_history_.WillDraw();
172 AdvanceNowBy(draw_duration);
173 timing_history_.DidDraw(false, false);
174
175 EXPECT_EQ(base::TimeDelta(),
176 timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
177 EXPECT_EQ(begin_main_frame_queue_duration,
178 timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
179
180 EXPECT_EQ(prepare_tiles_duration,
181 timing_history_.PrepareTilesDurationEstimate());
182 EXPECT_EQ(activate_duration, timing_history_.ActivateDurationEstimate());
183 EXPECT_EQ(draw_duration, timing_history_.DrawDurationEstimate());
184 }
185
TEST_F(CompositorTimingHistoryTest,BeginMainFrame_CriticalFaster)186 TEST_F(CompositorTimingHistoryTest, BeginMainFrame_CriticalFaster) {
187 // Critical BeginMainFrames are faster than non critical ones.
188 base::TimeDelta begin_main_frame_queue_duration_critical =
189 base::TimeDelta::FromMilliseconds(1);
190 base::TimeDelta begin_main_frame_queue_duration_not_critical =
191 base::TimeDelta::FromMilliseconds(2);
192 base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
193 base::TimeDelta::FromMilliseconds(1);
194
195 viz::BeginFrameArgs args_ = GetFakeBeginFrameArg();
196 timing_history_.WillBeginMainFrame(args_);
197 AdvanceNowBy(begin_main_frame_queue_duration_critical);
198 timing_history_.BeginMainFrameStarted(Now());
199 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
200 timing_history_.BeginMainFrameAborted(
201 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
202
203 args_ = GetFakeBeginFrameArg(false);
204 timing_history_.WillBeginMainFrame(args_);
205 AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
206 timing_history_.BeginMainFrameStarted(Now());
207 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
208 timing_history_.BeginMainFrameAborted(
209 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
210
211 // Since the critical BeginMainFrames are faster than non critical ones,
212 // the expectations are straightforward.
213 EXPECT_EQ(begin_main_frame_queue_duration_critical,
214 timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
215 EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
216 timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
217 }
218
TEST_F(CompositorTimingHistoryTest,BeginMainFrames_OldCriticalSlower)219 TEST_F(CompositorTimingHistoryTest, BeginMainFrames_OldCriticalSlower) {
220 // Critical BeginMainFrames are slower than non critical ones,
221 // which is unexpected, but could occur if one type of frame
222 // hasn't been sent for a significant amount of time.
223 base::TimeDelta begin_main_frame_queue_duration_critical =
224 base::TimeDelta::FromMilliseconds(2);
225 base::TimeDelta begin_main_frame_queue_duration_not_critical =
226 base::TimeDelta::FromMilliseconds(1);
227 base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
228 base::TimeDelta::FromMilliseconds(1);
229
230 // A single critical frame that is slow.
231 viz::BeginFrameArgs args_ = GetFakeBeginFrameArg();
232 timing_history_.WillBeginMainFrame(args_);
233 AdvanceNowBy(begin_main_frame_queue_duration_critical);
234 timing_history_.BeginMainFrameStarted(Now());
235 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
236 // BeginMainFrameAborted counts as a commit complete.
237 timing_history_.BeginMainFrameAborted(
238 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
239
240 // A bunch of faster non critical frames that are newer.
241 for (int i = 0; i < 100; i++) {
242 args_ = GetFakeBeginFrameArg(false);
243 timing_history_.WillBeginMainFrame(args_);
244 AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
245 timing_history_.BeginMainFrameStarted(Now());
246 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
247 // BeginMainFrameAborted counts as a commit complete.
248 timing_history_.BeginMainFrameAborted(
249 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
250 }
251
252 // Recent fast non critical BeginMainFrames should result in the
253 // critical estimate also being fast.
254 EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
255 timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
256 EXPECT_EQ(begin_main_frame_queue_duration_not_critical,
257 timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
258 }
259
TEST_F(CompositorTimingHistoryTest,BeginMainFrames_NewCriticalSlower)260 TEST_F(CompositorTimingHistoryTest, BeginMainFrames_NewCriticalSlower) {
261 // Critical BeginMainFrames are slower than non critical ones,
262 // which is unexpected, but could occur if one type of frame
263 // hasn't been sent for a significant amount of time.
264 base::TimeDelta begin_main_frame_queue_duration_critical =
265 base::TimeDelta::FromMilliseconds(2);
266 base::TimeDelta begin_main_frame_queue_duration_not_critical =
267 base::TimeDelta::FromMilliseconds(1);
268 base::TimeDelta begin_main_frame_start_to_ready_to_commit_duration =
269 base::TimeDelta::FromMilliseconds(1);
270
271 // A single non critical frame that is fast.
272 viz::BeginFrameArgs args_ = GetFakeBeginFrameArg(false);
273 timing_history_.WillBeginMainFrame(args_);
274 AdvanceNowBy(begin_main_frame_queue_duration_not_critical);
275 timing_history_.BeginMainFrameStarted(Now());
276 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
277 timing_history_.BeginMainFrameAborted(
278 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
279
280 // A bunch of slower critical frames that are newer.
281 for (int i = 0; i < 100; i++) {
282 args_ = GetFakeBeginFrameArg();
283 timing_history_.WillBeginMainFrame(args_);
284 AdvanceNowBy(begin_main_frame_queue_duration_critical);
285 timing_history_.BeginMainFrameStarted(Now());
286 AdvanceNowBy(begin_main_frame_start_to_ready_to_commit_duration);
287 timing_history_.BeginMainFrameAborted(
288 args_.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
289 }
290
291 // Recent slow critical BeginMainFrames should result in the
292 // not critical estimate also being slow.
293 EXPECT_EQ(begin_main_frame_queue_duration_critical,
294 timing_history_.BeginMainFrameQueueDurationCriticalEstimate());
295 EXPECT_EQ(begin_main_frame_queue_duration_critical,
296 timing_history_.BeginMainFrameQueueDurationNotCriticalEstimate());
297 }
298
TEST_F(CompositorTimingHistoryTest,DroppedFrameCountOnMainFrameAbort)299 TEST_F(CompositorTimingHistoryTest, DroppedFrameCountOnMainFrameAbort) {
300 DroppedFrameCounter c;
301 reporting_controller_->SetDroppedFrameCounter(&c);
302
303 // Start a few begin-main-frames, but abort the main-frames due to no damage.
304 for (int i = 0; i < 5; ++i) {
305 auto args = GetFakeBeginFrameArg(false);
306 timing_history_.WillBeginMainFrame(args);
307 timing_history_.BeginMainFrameStarted(Now());
308 timing_history_.BeginMainFrameAborted(
309 args.frame_id, CommitEarlyOutReason::FINISHED_NO_UPDATES);
310 }
311 EXPECT_EQ(0u, c.total_compositor_dropped());
312
313 // Start a few begin-main-frames, but abort the main-frames due to no damage.
314 for (int i = 0; i < 5; ++i) {
315 auto args = GetFakeBeginFrameArg(false);
316 timing_history_.WillBeginMainFrame(args);
317 timing_history_.BeginMainFrameStarted(Now());
318 timing_history_.BeginMainFrameAborted(
319 args.frame_id, CommitEarlyOutReason::ABORTED_DEFERRED_COMMIT);
320 }
321 timing_history_.WillBeginMainFrame(GetFakeBeginFrameArg());
322 EXPECT_EQ(5u, c.total_compositor_dropped());
323
324 reporting_controller_->SetDroppedFrameCounter(nullptr);
325 reporting_controller_ = nullptr;
326 }
327
328 } // namespace
329 } // namespace cc
330