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