1 /*
2 * Copyright 2018 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 // TODO(b/129481165): remove the #pragma below and fix conversion issues
18 #pragma clang diagnostic push
19 #pragma clang diagnostic ignored "-Wconversion"
20
21 #undef LOG_TAG
22 #define LOG_TAG "LibSurfaceFlingerUnittests"
23
24 #include <TimeStats/TimeStats.h>
25 #include <android/util/ProtoOutputStream.h>
26 #include <gmock/gmock.h>
27 #include <gtest/gtest.h>
28 #include <log/log.h>
29 #include <utils/String16.h>
30 #include <utils/Vector.h>
31
32 #include <chrono>
33 #include <random>
34 #include <unordered_set>
35
36 #include "libsurfaceflinger_unittest_main.h"
37
38 using namespace android::surfaceflinger;
39 using namespace google::protobuf;
40 using namespace std::chrono_literals;
41
42 namespace android {
43 namespace {
44
45 using testing::_;
46 using testing::AnyNumber;
47 using testing::Contains;
48 using testing::HasSubstr;
49 using testing::InSequence;
50 using testing::SizeIs;
51 using testing::StrEq;
52 using testing::UnorderedElementsAre;
53
54 using PowerMode = hardware::graphics::composer::V2_4::IComposerClient::PowerMode;
55
56 // clang-format off
57 #define FMT_PROTO true
58 #define FMT_STRING false
59 #define LAYER_ID_0 0
60 #define LAYER_ID_1 1
61 #define LAYER_ID_INVALID -1
62 #define NUM_LAYERS 1
63 #define NUM_LAYERS_INVALID "INVALID"
64
65 enum InputCommand : int32_t {
66 ENABLE = 0,
67 DISABLE = 1,
68 CLEAR = 2,
69 DUMP_ALL = 3,
70 DUMP_MAXLAYERS_1 = 4,
71 DUMP_MAXLAYERS_INVALID = 5,
72 INPUT_COMMAND_BEGIN = ENABLE,
73 INPUT_COMMAND_END = DUMP_MAXLAYERS_INVALID,
74 INPUT_COMMAND_RANGE = INPUT_COMMAND_END - INPUT_COMMAND_BEGIN + 1,
75 };
76
77 enum TimeStamp : int32_t {
78 POST = 0,
79 ACQUIRE = 1,
80 ACQUIRE_FENCE = 2,
81 LATCH = 3,
82 DESIRED = 4,
83 PRESENT = 5,
84 PRESENT_FENCE = 6,
85 TIME_STAMP_BEGIN = POST,
86 TIME_STAMP_END = PRESENT,
87 TIME_STAMP_RANGE = TIME_STAMP_END - TIME_STAMP_BEGIN + 1,
88 };
89
90 static const TimeStamp NORMAL_SEQUENCE[] = {
91 TimeStamp::POST,
92 TimeStamp::ACQUIRE,
93 TimeStamp::LATCH,
94 TimeStamp::DESIRED,
95 TimeStamp::PRESENT,
96 };
97
98 static const TimeStamp NORMAL_SEQUENCE_2[] = {
99 TimeStamp::POST,
100 TimeStamp::ACQUIRE_FENCE,
101 TimeStamp::LATCH,
102 TimeStamp::DESIRED,
103 TimeStamp::PRESENT_FENCE,
104 };
105
106 static const TimeStamp UNORDERED_SEQUENCE[] = {
107 TimeStamp::ACQUIRE,
108 TimeStamp::LATCH,
109 TimeStamp::POST,
110 TimeStamp::DESIRED,
111 TimeStamp::PRESENT,
112 };
113
114 static const TimeStamp INCOMPLETE_SEQUENCE[] = {
115 TimeStamp::POST,
116 };
117 // clang-format on
118
119 class TimeStatsTest : public testing::Test {
120 public:
TimeStatsTest()121 TimeStatsTest() {
122 const ::testing::TestInfo* const test_info =
123 ::testing::UnitTest::GetInstance()->current_test_info();
124 ALOGD("**** Setting up for %s.%s\n", test_info->test_case_name(), test_info->name());
125 }
126
~TimeStatsTest()127 ~TimeStatsTest() {
128 const ::testing::TestInfo* const test_info =
129 ::testing::UnitTest::GetInstance()->current_test_info();
130 ALOGD("**** Tearing down after %s.%s\n", test_info->test_case_name(), test_info->name());
131 }
132
133 std::string inputCommand(InputCommand cmd, bool useProto);
134
135 void setTimeStamp(TimeStamp type, int32_t id, uint64_t frameNumber, nsecs_t ts);
136
137 int32_t genRandomInt32(int32_t begin, int32_t end);
138
139 template <size_t N>
insertTimeRecord(const TimeStamp (& sequence)[N],int32_t id,uint64_t frameNumber,nsecs_t ts)140 void insertTimeRecord(const TimeStamp (&sequence)[N], int32_t id, uint64_t frameNumber,
141 nsecs_t ts) {
142 for (size_t i = 0; i < N; i++, ts += 1000000) {
143 setTimeStamp(sequence[i], id, frameNumber, ts);
144 }
145 }
146
147 std::mt19937 mRandomEngine = std::mt19937(std::random_device()());
148
149 class FakeStatsEventDelegate : public impl::TimeStats::StatsEventDelegate {
150 public:
151 FakeStatsEventDelegate() = default;
152 ~FakeStatsEventDelegate() override = default;
153
addStatsEventToPullData(AStatsEventList *)154 struct AStatsEvent* addStatsEventToPullData(AStatsEventList*) override {
155 return mEvent;
156 }
setStatsPullAtomCallback(int32_t atom_tag,AStatsManager_PullAtomMetadata *,AStatsManager_PullAtomCallback callback,void * cookie)157 void setStatsPullAtomCallback(int32_t atom_tag, AStatsManager_PullAtomMetadata*,
158 AStatsManager_PullAtomCallback callback,
159 void* cookie) override {
160 mAtomTags.push_back(atom_tag);
161 mCallback = callback;
162 mCookie = cookie;
163 }
164
makePullAtomCallback(int32_t atom_tag,void * cookie)165 AStatsManager_PullAtomCallbackReturn makePullAtomCallback(int32_t atom_tag, void* cookie) {
166 return (*mCallback)(atom_tag, nullptr, cookie);
167 }
168
169 MOCK_METHOD1(clearStatsPullAtomCallback, void(int32_t));
170 MOCK_METHOD2(statsEventSetAtomId, void(AStatsEvent*, uint32_t));
171 MOCK_METHOD2(statsEventWriteInt32, void(AStatsEvent*, int32_t));
172 MOCK_METHOD2(statsEventWriteInt64, void(AStatsEvent*, int64_t));
173 MOCK_METHOD2(statsEventWriteString8, void(AStatsEvent*, const char*));
174 MOCK_METHOD3(statsEventWriteByteArray, void(AStatsEvent*, const uint8_t*, size_t));
175 MOCK_METHOD1(statsEventBuild, void(AStatsEvent*));
176
177 AStatsEvent* mEvent = AStatsEvent_obtain();
178 std::vector<int32_t> mAtomTags;
179 AStatsManager_PullAtomCallback mCallback = nullptr;
180 void* mCookie = nullptr;
181 };
182 FakeStatsEventDelegate* mDelegate = new FakeStatsEventDelegate;
183 std::unique_ptr<TimeStats> mTimeStats =
184 std::make_unique<impl::TimeStats>(std::unique_ptr<FakeStatsEventDelegate>(mDelegate),
185 std::nullopt, std::nullopt);
186 };
187
inputCommand(InputCommand cmd,bool useProto)188 std::string TimeStatsTest::inputCommand(InputCommand cmd, bool useProto) {
189 std::string result;
190 Vector<String16> args;
191
192 switch (cmd) {
193 case InputCommand::ENABLE:
194 args.push_back(String16("-enable"));
195 break;
196 case InputCommand::DISABLE:
197 args.push_back(String16("-disable"));
198 break;
199 case InputCommand::CLEAR:
200 args.push_back(String16("-clear"));
201 break;
202 case InputCommand::DUMP_ALL:
203 args.push_back(String16("-dump"));
204 break;
205 case InputCommand::DUMP_MAXLAYERS_1:
206 args.push_back(String16("-dump"));
207 args.push_back(String16("-maxlayers"));
208 args.push_back(String16(std::to_string(NUM_LAYERS).c_str()));
209 break;
210 case InputCommand::DUMP_MAXLAYERS_INVALID:
211 args.push_back(String16("-dump"));
212 args.push_back(String16("-maxlayers"));
213 args.push_back(String16(NUM_LAYERS_INVALID));
214 break;
215 default:
216 ALOGD("Invalid control command");
217 }
218
219 EXPECT_NO_FATAL_FAILURE(mTimeStats->parseArgs(useProto, args, result));
220 return result;
221 }
222
genLayerName(int32_t layerId)223 static std::string genLayerName(int32_t layerId) {
224 return (layerId < 0 ? "PopupWindow:b54fcd1#0" : "com.dummy#") + std::to_string(layerId);
225 }
226
setTimeStamp(TimeStamp type,int32_t id,uint64_t frameNumber,nsecs_t ts)227 void TimeStatsTest::setTimeStamp(TimeStamp type, int32_t id, uint64_t frameNumber, nsecs_t ts) {
228 switch (type) {
229 case TimeStamp::POST:
230 ASSERT_NO_FATAL_FAILURE(mTimeStats->setPostTime(id, frameNumber, genLayerName(id), ts));
231 break;
232 case TimeStamp::ACQUIRE:
233 ASSERT_NO_FATAL_FAILURE(mTimeStats->setAcquireTime(id, frameNumber, ts));
234 break;
235 case TimeStamp::ACQUIRE_FENCE:
236 ASSERT_NO_FATAL_FAILURE(
237 mTimeStats->setAcquireFence(id, frameNumber, std::make_shared<FenceTime>(ts)));
238 break;
239 case TimeStamp::LATCH:
240 ASSERT_NO_FATAL_FAILURE(mTimeStats->setLatchTime(id, frameNumber, ts));
241 break;
242 case TimeStamp::DESIRED:
243 ASSERT_NO_FATAL_FAILURE(mTimeStats->setDesiredTime(id, frameNumber, ts));
244 break;
245 case TimeStamp::PRESENT:
246 ASSERT_NO_FATAL_FAILURE(mTimeStats->setPresentTime(id, frameNumber, ts));
247 break;
248 case TimeStamp::PRESENT_FENCE:
249 ASSERT_NO_FATAL_FAILURE(
250 mTimeStats->setPresentFence(id, frameNumber, std::make_shared<FenceTime>(ts)));
251 break;
252 default:
253 ALOGD("Invalid timestamp type");
254 }
255 }
256
genRandomInt32(int32_t begin,int32_t end)257 int32_t TimeStatsTest::genRandomInt32(int32_t begin, int32_t end) {
258 std::uniform_int_distribution<int32_t> distr(begin, end);
259 return distr(mRandomEngine);
260 }
261
TEST_F(TimeStatsTest,disabledByDefault)262 TEST_F(TimeStatsTest, disabledByDefault) {
263 ASSERT_FALSE(mTimeStats->isEnabled());
264 }
265
TEST_F(TimeStatsTest,setsCallbacksAfterBoot)266 TEST_F(TimeStatsTest, setsCallbacksAfterBoot) {
267 mTimeStats->onBootFinished();
268 EXPECT_THAT(mDelegate->mAtomTags,
269 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
270 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
271 }
272
TEST_F(TimeStatsTest,clearsCallbacksOnDestruction)273 TEST_F(TimeStatsTest, clearsCallbacksOnDestruction) {
274 EXPECT_CALL(*mDelegate,
275 clearStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO));
276 EXPECT_CALL(*mDelegate,
277 clearStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO));
278 mTimeStats.reset();
279 }
280
TEST_F(TimeStatsTest,canEnableAndDisableTimeStats)281 TEST_F(TimeStatsTest, canEnableAndDisableTimeStats) {
282 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
283 ASSERT_TRUE(mTimeStats->isEnabled());
284
285 EXPECT_TRUE(inputCommand(InputCommand::DISABLE, FMT_STRING).empty());
286 ASSERT_FALSE(mTimeStats->isEnabled());
287 }
288
TEST_F(TimeStatsTest,canIncreaseGlobalStats)289 TEST_F(TimeStatsTest, canIncreaseGlobalStats) {
290 constexpr size_t TOTAL_FRAMES = 5;
291 constexpr size_t MISSED_FRAMES = 4;
292 constexpr size_t CLIENT_COMPOSITION_FRAMES = 3;
293
294 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
295
296 for (size_t i = 0; i < TOTAL_FRAMES; i++) {
297 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementTotalFrames());
298 }
299 for (size_t i = 0; i < MISSED_FRAMES; i++) {
300 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementMissedFrames());
301 }
302 for (size_t i = 0; i < CLIENT_COMPOSITION_FRAMES; i++) {
303 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionFrames());
304 }
305
306 SFTimeStatsGlobalProto globalProto;
307 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
308
309 ASSERT_TRUE(globalProto.has_total_frames());
310 EXPECT_EQ(TOTAL_FRAMES, globalProto.total_frames());
311 ASSERT_TRUE(globalProto.has_missed_frames());
312 EXPECT_EQ(MISSED_FRAMES, globalProto.missed_frames());
313 ASSERT_TRUE(globalProto.has_client_composition_frames());
314 EXPECT_EQ(CLIENT_COMPOSITION_FRAMES, globalProto.client_composition_frames());
315 }
316
TEST_F(TimeStatsTest,canIncreaseLateAcquireFrames)317 TEST_F(TimeStatsTest, canIncreaseLateAcquireFrames) {
318 // this stat is not in the proto so verify by checking the string dump
319 constexpr size_t LATE_ACQUIRE_FRAMES = 2;
320
321 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
322
323 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
324 for (size_t i = 0; i < LATE_ACQUIRE_FRAMES; i++) {
325 mTimeStats->incrementLatchSkipped(LAYER_ID_0, TimeStats::LatchSkipReason::LateAcquire);
326 }
327 insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
328
329 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
330 const std::string expectedResult = "lateAcquireFrames = " + std::to_string(LATE_ACQUIRE_FRAMES);
331 EXPECT_THAT(result, HasSubstr(expectedResult));
332 }
333
TEST_F(TimeStatsTest,canIncreaseBadDesiredPresent)334 TEST_F(TimeStatsTest, canIncreaseBadDesiredPresent) {
335 // this stat is not in the proto so verify by checking the string dump
336 constexpr size_t BAD_DESIRED_PRESENT_FRAMES = 2;
337
338 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
339
340 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
341 for (size_t i = 0; i < BAD_DESIRED_PRESENT_FRAMES; i++) {
342 mTimeStats->incrementBadDesiredPresent(LAYER_ID_0);
343 }
344 insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
345
346 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
347 const std::string expectedResult =
348 "badDesiredPresentFrames = " + std::to_string(BAD_DESIRED_PRESENT_FRAMES);
349 EXPECT_THAT(result, HasSubstr(expectedResult));
350 }
351
TEST_F(TimeStatsTest,canIncreaseClientCompositionReusedFrames)352 TEST_F(TimeStatsTest, canIncreaseClientCompositionReusedFrames) {
353 // this stat is not in the proto so verify by checking the string dump
354 constexpr size_t CLIENT_COMPOSITION_REUSED_FRAMES = 2;
355
356 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
357 for (size_t i = 0; i < CLIENT_COMPOSITION_REUSED_FRAMES; i++) {
358 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionReusedFrames());
359 }
360
361 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
362 const std::string expectedResult =
363 "clientCompositionReusedFrames = " + std::to_string(CLIENT_COMPOSITION_REUSED_FRAMES);
364 EXPECT_THAT(result, HasSubstr(expectedResult));
365 }
366
TEST_F(TimeStatsTest,canIncreaseRefreshRateSwitches)367 TEST_F(TimeStatsTest, canIncreaseRefreshRateSwitches) {
368 // this stat is not in the proto so verify by checking the string dump
369 constexpr size_t REFRESH_RATE_SWITCHES = 2;
370
371 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
372 for (size_t i = 0; i < REFRESH_RATE_SWITCHES; i++) {
373 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementRefreshRateSwitches());
374 }
375
376 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
377 const std::string expectedResult =
378 "refreshRateSwitches = " + std::to_string(REFRESH_RATE_SWITCHES);
379 EXPECT_THAT(result, HasSubstr(expectedResult));
380 }
381
TEST_F(TimeStatsTest,canIncreaseCompositionStrategyChanges)382 TEST_F(TimeStatsTest, canIncreaseCompositionStrategyChanges) {
383 // this stat is not in the proto so verify by checking the string dump
384 constexpr size_t COMPOSITION_STRATEGY_CHANGES = 2;
385
386 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
387 for (size_t i = 0; i < COMPOSITION_STRATEGY_CHANGES; i++) {
388 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementCompositionStrategyChanges());
389 }
390
391 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
392 const std::string expectedResult =
393 "compositionStrategyChanges = " + std::to_string(COMPOSITION_STRATEGY_CHANGES);
394 EXPECT_THAT(result, HasSubstr(expectedResult));
395 }
396
TEST_F(TimeStatsTest,canAverageFrameDuration)397 TEST_F(TimeStatsTest, canAverageFrameDuration) {
398 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
399 mTimeStats->setPowerMode(PowerMode::ON);
400 mTimeStats
401 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(),
402 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
403 .count());
404 mTimeStats
405 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(),
406 std::chrono::duration_cast<std::chrono::nanoseconds>(16ms)
407 .count());
408
409 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
410 EXPECT_THAT(result, HasSubstr("averageFrameDuration = 10.000 ms"));
411 }
412
TEST_F(TimeStatsTest,canAverageRenderEngineTimings)413 TEST_F(TimeStatsTest, canAverageRenderEngineTimings) {
414 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
415 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms)
416 .count(),
417 std::make_shared<FenceTime>(
418 std::chrono::duration_cast<
419 std::chrono::nanoseconds>(3ms)
420 .count()));
421
422 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms)
423 .count(),
424 std::chrono::duration_cast<std::chrono::nanoseconds>(8ms)
425 .count());
426
427 // Push a dummy present fence to trigger flushing the RenderEngine timings.
428 mTimeStats->setPowerMode(PowerMode::ON);
429 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(
430 std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count()));
431
432 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
433 EXPECT_THAT(result, HasSubstr("averageRenderEngineTiming = 3.000 ms"));
434 }
435
TEST_F(TimeStatsTest,canInsertGlobalPresentToPresent)436 TEST_F(TimeStatsTest, canInsertGlobalPresentToPresent) {
437 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
438
439 ASSERT_NO_FATAL_FAILURE(
440 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(1000000)));
441 ASSERT_NO_FATAL_FAILURE(
442 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(2000000)));
443
444 ASSERT_NO_FATAL_FAILURE(mTimeStats->setPowerMode(PowerMode::ON));
445 ASSERT_NO_FATAL_FAILURE(
446 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(3000000)));
447 ASSERT_NO_FATAL_FAILURE(
448 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(5000000)));
449
450 ASSERT_NO_FATAL_FAILURE(mTimeStats->setPowerMode(PowerMode::OFF));
451 ASSERT_NO_FATAL_FAILURE(
452 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(6000000)));
453 ASSERT_NO_FATAL_FAILURE(
454 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(8000000)));
455
456 SFTimeStatsGlobalProto globalProto;
457 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
458
459 ASSERT_EQ(1, globalProto.present_to_present_size());
460 const SFTimeStatsHistogramBucketProto& histogramProto = globalProto.present_to_present().Get(0);
461 EXPECT_EQ(1, histogramProto.frame_count());
462 EXPECT_EQ(2, histogramProto.time_millis());
463 }
464
TEST_F(TimeStatsTest,canInsertGlobalFrameDuration)465 TEST_F(TimeStatsTest, canInsertGlobalFrameDuration) {
466 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
467
468 mTimeStats->setPowerMode(PowerMode::OFF);
469 mTimeStats
470 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(),
471 std::chrono::duration_cast<std::chrono::nanoseconds>(5ms)
472 .count());
473 mTimeStats->setPowerMode(PowerMode::ON);
474 mTimeStats
475 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(3ms).count(),
476 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
477 .count());
478
479 SFTimeStatsGlobalProto globalProto;
480 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
481
482 ASSERT_EQ(1, globalProto.frame_duration_size());
483 const SFTimeStatsHistogramBucketProto& histogramProto = globalProto.frame_duration().Get(0);
484 EXPECT_EQ(1, histogramProto.frame_count());
485 EXPECT_EQ(3, histogramProto.time_millis());
486 }
487
TEST_F(TimeStatsTest,canInsertGlobalRenderEngineTiming)488 TEST_F(TimeStatsTest, canInsertGlobalRenderEngineTiming) {
489 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
490
491 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms)
492 .count(),
493 std::make_shared<FenceTime>(
494 std::chrono::duration_cast<
495 std::chrono::nanoseconds>(3ms)
496 .count()));
497
498 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms)
499 .count(),
500 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
501 .count());
502
503 // First verify that flushing RenderEngine durations did not occur yet.
504 SFTimeStatsGlobalProto preFlushProto;
505 ASSERT_TRUE(preFlushProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
506 ASSERT_EQ(0, preFlushProto.render_engine_timing_size());
507
508 // Push a dummy present fence to trigger flushing the RenderEngine timings.
509 mTimeStats->setPowerMode(PowerMode::ON);
510 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(
511 std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count()));
512
513 // Now we can verify that RenderEngine durations were flushed now.
514 SFTimeStatsGlobalProto postFlushProto;
515 ASSERT_TRUE(postFlushProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
516
517 ASSERT_EQ(1, postFlushProto.render_engine_timing_size());
518 const SFTimeStatsHistogramBucketProto& histogramProto =
519 postFlushProto.render_engine_timing().Get(0);
520 EXPECT_EQ(2, histogramProto.frame_count());
521 EXPECT_EQ(2, histogramProto.time_millis());
522 }
523
TEST_F(TimeStatsTest,canInsertOneLayerTimeStats)524 TEST_F(TimeStatsTest, canInsertOneLayerTimeStats) {
525 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
526
527 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
528 insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
529
530 SFTimeStatsGlobalProto globalProto;
531 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
532
533 ASSERT_EQ(1, globalProto.stats_size());
534 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
535 ASSERT_TRUE(layerProto.has_layer_name());
536 EXPECT_EQ(genLayerName(LAYER_ID_0), layerProto.layer_name());
537 ASSERT_TRUE(layerProto.has_total_frames());
538 EXPECT_EQ(1, layerProto.total_frames());
539 ASSERT_EQ(6, layerProto.deltas_size());
540 for (const SFTimeStatsDeltaProto& deltaProto : layerProto.deltas()) {
541 ASSERT_EQ(1, deltaProto.histograms_size());
542 const SFTimeStatsHistogramBucketProto& histogramProto = deltaProto.histograms().Get(0);
543 EXPECT_EQ(1, histogramProto.frame_count());
544 if ("post2acquire" == deltaProto.delta_name()) {
545 EXPECT_EQ(1, histogramProto.time_millis());
546 } else if ("post2present" == deltaProto.delta_name()) {
547 EXPECT_EQ(4, histogramProto.time_millis());
548 } else if ("acquire2present" == deltaProto.delta_name()) {
549 EXPECT_EQ(3, histogramProto.time_millis());
550 } else if ("latch2present" == deltaProto.delta_name()) {
551 EXPECT_EQ(2, histogramProto.time_millis());
552 } else if ("desired2present" == deltaProto.delta_name()) {
553 EXPECT_EQ(1, histogramProto.time_millis());
554 } else if ("present2present" == deltaProto.delta_name()) {
555 EXPECT_EQ(1, histogramProto.time_millis());
556 } else {
557 FAIL() << "Unknown delta_name: " << deltaProto.delta_name();
558 }
559 }
560 }
561
TEST_F(TimeStatsTest,canNotInsertInvalidLayerNameTimeStats)562 TEST_F(TimeStatsTest, canNotInsertInvalidLayerNameTimeStats) {
563 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
564
565 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_INVALID, 1, 1000000);
566 insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_INVALID, 2, 2000000);
567
568 SFTimeStatsGlobalProto globalProto;
569 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
570
571 ASSERT_EQ(0, globalProto.stats_size());
572 }
573
TEST_F(TimeStatsTest,canInsertMultipleLayersTimeStats)574 TEST_F(TimeStatsTest, canInsertMultipleLayersTimeStats) {
575 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
576
577 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
578 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 1, 1000000);
579 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
580 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 2, 2000000);
581
582 SFTimeStatsGlobalProto globalProto;
583 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
584
585 EXPECT_EQ(2, globalProto.stats_size());
586 }
587
TEST_F(TimeStatsTest,canInsertUnorderedLayerTimeStats)588 TEST_F(TimeStatsTest, canInsertUnorderedLayerTimeStats) {
589 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
590
591 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
592 insertTimeRecord(UNORDERED_SEQUENCE, LAYER_ID_0, 2, 2000000);
593
594 SFTimeStatsGlobalProto globalProto;
595 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
596
597 ASSERT_EQ(1, globalProto.stats_size());
598 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
599 ASSERT_TRUE(layerProto.has_layer_name());
600 EXPECT_EQ(genLayerName(LAYER_ID_0), layerProto.layer_name());
601 ASSERT_TRUE(layerProto.has_total_frames());
602 EXPECT_EQ(1, layerProto.total_frames());
603 ASSERT_EQ(6, layerProto.deltas_size());
604 for (const SFTimeStatsDeltaProto& deltaProto : layerProto.deltas()) {
605 ASSERT_EQ(1, deltaProto.histograms_size());
606 const SFTimeStatsHistogramBucketProto& histogramProto = deltaProto.histograms().Get(0);
607 EXPECT_EQ(1, histogramProto.frame_count());
608 if ("post2acquire" == deltaProto.delta_name()) {
609 EXPECT_EQ(0, histogramProto.time_millis());
610 } else if ("post2present" == deltaProto.delta_name()) {
611 EXPECT_EQ(2, histogramProto.time_millis());
612 } else if ("acquire2present" == deltaProto.delta_name()) {
613 EXPECT_EQ(2, histogramProto.time_millis());
614 } else if ("latch2present" == deltaProto.delta_name()) {
615 EXPECT_EQ(2, histogramProto.time_millis());
616 } else if ("desired2present" == deltaProto.delta_name()) {
617 EXPECT_EQ(1, histogramProto.time_millis());
618 } else if ("present2present" == deltaProto.delta_name()) {
619 EXPECT_EQ(1, histogramProto.time_millis());
620 } else {
621 FAIL() << "Unknown delta_name: " << deltaProto.delta_name();
622 }
623 }
624 }
625
TEST_F(TimeStatsTest,recordRefreshRateNewConfigs)626 TEST_F(TimeStatsTest, recordRefreshRateNewConfigs) {
627 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
628
629 uint32_t fpsOne = 30;
630 uint32_t fpsTwo = 90;
631 uint64_t millisOne = 5000;
632 uint64_t millisTwo = 7000;
633
634 mTimeStats->recordRefreshRate(fpsOne, ms2ns(millisOne));
635 mTimeStats->recordRefreshRate(fpsTwo, ms2ns(millisTwo));
636
637 SFTimeStatsGlobalProto globalProto;
638 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
639
640 SFTimeStatsDisplayConfigBucketProto expectedBucketOne;
641 SFTimeStatsDisplayConfigProto* expectedConfigOne = expectedBucketOne.mutable_config();
642 expectedConfigOne->set_fps(fpsOne);
643 expectedBucketOne.set_duration_millis(millisOne);
644
645 SFTimeStatsDisplayConfigBucketProto expectedBucketTwo;
646 SFTimeStatsDisplayConfigProto* expectedConfigTwo = expectedBucketTwo.mutable_config();
647 expectedConfigTwo->set_fps(fpsTwo);
648 expectedBucketTwo.set_duration_millis(millisTwo);
649
650 EXPECT_THAT(globalProto.display_config_stats(), SizeIs(2));
651
652 std::unordered_set<uint32_t> seen_fps;
653 for (const auto& bucket : globalProto.display_config_stats()) {
654 seen_fps.emplace(bucket.config().fps());
655 if (fpsOne == bucket.config().fps()) {
656 EXPECT_EQ(millisOne, bucket.duration_millis());
657 } else if (fpsTwo == bucket.config().fps()) {
658 EXPECT_EQ(millisTwo, bucket.duration_millis());
659 } else {
660 FAIL() << "Unknown fps: " << bucket.config().fps();
661 }
662 }
663 EXPECT_THAT(seen_fps, UnorderedElementsAre(fpsOne, fpsTwo));
664 }
665
TEST_F(TimeStatsTest,recordRefreshRateUpdatesConfig)666 TEST_F(TimeStatsTest, recordRefreshRateUpdatesConfig) {
667 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
668
669 uint32_t fps = 30;
670 uint64_t millisOne = 5000;
671 uint64_t millisTwo = 7000;
672
673 mTimeStats->recordRefreshRate(fps, ms2ns(millisOne));
674 mTimeStats->recordRefreshRate(fps, ms2ns(millisTwo));
675
676 SFTimeStatsGlobalProto globalProto;
677 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
678 EXPECT_THAT(globalProto.display_config_stats(), SizeIs(1));
679 EXPECT_EQ(fps, globalProto.display_config_stats().Get(0).config().fps());
680 EXPECT_EQ(millisOne + millisTwo, globalProto.display_config_stats().Get(0).duration_millis());
681 }
682
TEST_F(TimeStatsTest,canRemoveTimeRecord)683 TEST_F(TimeStatsTest, canRemoveTimeRecord) {
684 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
685
686 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
687 insertTimeRecord(INCOMPLETE_SEQUENCE, LAYER_ID_0, 2, 2000000);
688 ASSERT_NO_FATAL_FAILURE(mTimeStats->removeTimeRecord(0, 2));
689 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 3, 3000000);
690
691 SFTimeStatsGlobalProto globalProto;
692 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
693
694 ASSERT_EQ(1, globalProto.stats_size());
695 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
696 ASSERT_TRUE(layerProto.has_total_frames());
697 EXPECT_EQ(1, layerProto.total_frames());
698 }
699
TEST_F(TimeStatsTest,canRecoverFromIncompleteTimeRecordError)700 TEST_F(TimeStatsTest, canRecoverFromIncompleteTimeRecordError) {
701 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
702
703 uint64_t frameNumber = 1;
704 nsecs_t ts = 1000000;
705 insertTimeRecord(INCOMPLETE_SEQUENCE, LAYER_ID_0, 1, 1000000);
706 for (size_t i = 0; i < impl::TimeStats::MAX_NUM_TIME_RECORDS + 2; i++) {
707 frameNumber++;
708 ts += 1000000;
709 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, frameNumber, ts);
710 }
711
712 SFTimeStatsGlobalProto globalProto;
713 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
714
715 ASSERT_EQ(1, globalProto.stats_size());
716 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
717 ASSERT_TRUE(layerProto.has_total_frames());
718 EXPECT_EQ(1, layerProto.total_frames());
719 }
720
TEST_F(TimeStatsTest,layerTimeStatsOnDestroy)721 TEST_F(TimeStatsTest, layerTimeStatsOnDestroy) {
722 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
723
724 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
725 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
726 ASSERT_NO_FATAL_FAILURE(mTimeStats->onDestroy(0));
727 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 3, 3000000);
728
729 SFTimeStatsGlobalProto globalProto;
730 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
731
732 ASSERT_EQ(1, globalProto.stats_size());
733 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
734 ASSERT_TRUE(layerProto.has_total_frames());
735 EXPECT_EQ(1, layerProto.total_frames());
736 }
737
TEST_F(TimeStatsTest,canClearTimeStats)738 TEST_F(TimeStatsTest, canClearTimeStats) {
739 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
740
741 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementTotalFrames());
742 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementMissedFrames());
743 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionFrames());
744 ASSERT_NO_FATAL_FAILURE(mTimeStats->setPowerMode(PowerMode::ON));
745
746 mTimeStats
747 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(3ms).count(),
748 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
749 .count());
750 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms)
751 .count(),
752 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
753 .count());
754 ASSERT_NO_FATAL_FAILURE(
755 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(1000000)));
756 ASSERT_NO_FATAL_FAILURE(
757 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(2000000)));
758 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
759 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
760
761 EXPECT_TRUE(inputCommand(InputCommand::CLEAR, FMT_STRING).empty());
762
763 SFTimeStatsGlobalProto globalProto;
764 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
765
766 EXPECT_EQ(0, globalProto.total_frames());
767 EXPECT_EQ(0, globalProto.missed_frames());
768 EXPECT_EQ(0, globalProto.client_composition_frames());
769 EXPECT_EQ(0, globalProto.present_to_present_size());
770 EXPECT_EQ(0, globalProto.frame_duration_size());
771 EXPECT_EQ(0, globalProto.render_engine_timing_size());
772 EXPECT_EQ(0, globalProto.stats_size());
773 }
774
TEST_F(TimeStatsTest,canClearDumpOnlyTimeStats)775 TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) {
776 // These stats are not in the proto so verify by checking the string dump.
777 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
778 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionReusedFrames());
779 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementRefreshRateSwitches());
780 ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementCompositionStrategyChanges());
781 mTimeStats->setPowerMode(PowerMode::ON);
782 mTimeStats
783 ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(),
784 std::chrono::duration_cast<std::chrono::nanoseconds>(5ms)
785 .count());
786 mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms)
787 .count(),
788 std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
789 .count());
790 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(
791 std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count()));
792 EXPECT_TRUE(inputCommand(InputCommand::CLEAR, FMT_STRING).empty());
793
794 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
795 EXPECT_THAT(result, HasSubstr("clientCompositionReusedFrames = 0"));
796 EXPECT_THAT(result, HasSubstr("refreshRateSwitches = 0"));
797 EXPECT_THAT(result, HasSubstr("compositionStrategyChanges = 0"));
798 EXPECT_THAT(result, HasSubstr("averageFrameDuration = 0.000 ms"));
799 EXPECT_THAT(result, HasSubstr("averageRenderEngineTiming = 0.000 ms"));
800 }
801
TEST_F(TimeStatsTest,canDumpWithMaxLayers)802 TEST_F(TimeStatsTest, canDumpWithMaxLayers) {
803 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
804
805 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
806 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 1, 1000000);
807 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
808 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 2, 2000000);
809 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 3, 2000000);
810
811 SFTimeStatsGlobalProto globalProto;
812 ASSERT_TRUE(
813 globalProto.ParseFromString(inputCommand(InputCommand::DUMP_MAXLAYERS_1, FMT_PROTO)));
814
815 ASSERT_EQ(1, globalProto.stats_size());
816 const SFTimeStatsLayerProto& layerProto = globalProto.stats().Get(0);
817 ASSERT_TRUE(layerProto.has_layer_name());
818 EXPECT_EQ(genLayerName(LAYER_ID_1), layerProto.layer_name());
819 ASSERT_TRUE(layerProto.has_total_frames());
820 EXPECT_EQ(2, layerProto.total_frames());
821 }
822
TEST_F(TimeStatsTest,canDumpWithInvalidMaxLayers)823 TEST_F(TimeStatsTest, canDumpWithInvalidMaxLayers) {
824 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
825
826 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
827 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
828
829 SFTimeStatsGlobalProto globalProto;
830 ASSERT_TRUE(globalProto.ParseFromString(
831 inputCommand(InputCommand::DUMP_MAXLAYERS_INVALID, FMT_PROTO)));
832
833 ASSERT_EQ(0, globalProto.stats_size());
834 }
835
TEST_F(TimeStatsTest,noInfInAverageFPS)836 TEST_F(TimeStatsTest, noInfInAverageFPS) {
837 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
838 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
839 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 1000000);
840
841 const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
842 EXPECT_THAT(result, HasSubstr("averageFPS = 0.000"));
843 }
844
845 namespace {
buildExpectedHistogramBytestring(const std::vector<int32_t> & times,const std::vector<int32_t> & frameCounts)846 std::string buildExpectedHistogramBytestring(const std::vector<int32_t>& times,
847 const std::vector<int32_t>& frameCounts) {
848 util::ProtoOutputStream proto;
849 for (int i = 0; i < times.size(); i++) {
850 ALOGE("Writing time: %d", times[i]);
851 proto.write(util::FIELD_TYPE_INT32 | util::FIELD_COUNT_REPEATED | 1 /* field id */,
852 (int32_t)times[i]);
853 ALOGE("Writing count: %d", frameCounts[i]);
854 proto.write(util::FIELD_TYPE_INT64 | util::FIELD_COUNT_REPEATED | 2 /* field id */,
855 (int64_t)frameCounts[i]);
856 }
857 std::string byteString;
858 proto.serializeToString(&byteString);
859 return byteString;
860 }
861
dumpByteStringHex(const std::string & str)862 std::string dumpByteStringHex(const std::string& str) {
863 std::stringstream ss;
864 ss << std::hex;
865 for (const char& c : str) {
866 ss << (int)c << " ";
867 }
868
869 return ss.str();
870 }
871
872 } // namespace
873
874 MATCHER_P2(BytesEq, bytes, size, "") {
875 std::string expected;
876 expected.append((const char*)bytes, size);
877 std::string actual;
878 actual.append((const char*)arg, size);
879
880 *result_listener << "Bytes are not equal! \n";
881 *result_listener << "size: " << size << "\n";
882 *result_listener << "expected: " << dumpByteStringHex(expected).c_str() << "\n";
883 *result_listener << "actual: " << dumpByteStringHex(actual).c_str() << "\n";
884
885 return expected == actual;
886 }
887
TEST_F(TimeStatsTest,globalStatsCallback)888 TEST_F(TimeStatsTest, globalStatsCallback) {
889 constexpr size_t TOTAL_FRAMES = 5;
890 constexpr size_t MISSED_FRAMES = 4;
891 constexpr size_t CLIENT_COMPOSITION_FRAMES = 3;
892 constexpr size_t DISPLAY_EVENT_CONNECTIONS = 14;
893
894 mTimeStats->onBootFinished();
895 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
896
897 for (size_t i = 0; i < TOTAL_FRAMES; i++) {
898 mTimeStats->incrementTotalFrames();
899 }
900 for (size_t i = 0; i < MISSED_FRAMES; i++) {
901 mTimeStats->incrementMissedFrames();
902 }
903 for (size_t i = 0; i < CLIENT_COMPOSITION_FRAMES; i++) {
904 mTimeStats->incrementClientCompositionFrames();
905 }
906
907 mTimeStats->recordDisplayEventConnectionCount(DISPLAY_EVENT_CONNECTIONS);
908 mTimeStats->setPowerMode(PowerMode::ON);
909 mTimeStats->recordFrameDuration(1000000, 3000000);
910 mTimeStats->recordRenderEngineDuration(2000000, 4000000);
911 mTimeStats->recordRenderEngineDuration(2000000, std::make_shared<FenceTime>(3000000));
912
913 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(3000000));
914 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(5000000));
915
916 EXPECT_THAT(mDelegate->mAtomTags,
917 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
918 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
919 EXPECT_NE(nullptr, mDelegate->mCallback);
920 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
921
922 std::string expectedFrameDuration = buildExpectedHistogramBytestring({2}, {1});
923 std::string expectedRenderEngineTiming = buildExpectedHistogramBytestring({1, 2}, {1, 1});
924
925 {
926 InSequence seq;
927 EXPECT_CALL(*mDelegate,
928 statsEventSetAtomId(mDelegate->mEvent,
929 android::util::SURFACEFLINGER_STATS_GLOBAL_INFO));
930 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, TOTAL_FRAMES));
931 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, MISSED_FRAMES));
932 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, CLIENT_COMPOSITION_FRAMES));
933 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, _));
934 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, 2));
935 EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, DISPLAY_EVENT_CONNECTIONS));
936 EXPECT_CALL(*mDelegate,
937 statsEventWriteByteArray(mDelegate->mEvent,
938 BytesEq((const uint8_t*)expectedFrameDuration.c_str(),
939 expectedFrameDuration.size()),
940 expectedFrameDuration.size()));
941 EXPECT_CALL(*mDelegate,
942 statsEventWriteByteArray(mDelegate->mEvent,
943 BytesEq((const uint8_t*)
944 expectedRenderEngineTiming.c_str(),
945 expectedRenderEngineTiming.size()),
946 expectedRenderEngineTiming.size()));
947 EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent));
948 }
949 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
950 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
951 mDelegate->mCookie));
952
953 SFTimeStatsGlobalProto globalProto;
954 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
955
956 EXPECT_EQ(0, globalProto.total_frames());
957 EXPECT_EQ(0, globalProto.missed_frames());
958 EXPECT_EQ(0, globalProto.client_composition_frames());
959 EXPECT_EQ(0, globalProto.present_to_present_size());
960 }
961
TEST_F(TimeStatsTest,layerStatsCallback_pullsAllAndClears)962 TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) {
963 constexpr size_t LATE_ACQUIRE_FRAMES = 2;
964 constexpr size_t BAD_DESIRED_PRESENT_FRAMES = 3;
965 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
966
967 mTimeStats->onBootFinished();
968
969 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
970 for (size_t i = 0; i < LATE_ACQUIRE_FRAMES; i++) {
971 mTimeStats->incrementLatchSkipped(LAYER_ID_0, TimeStats::LatchSkipReason::LateAcquire);
972 }
973 for (size_t i = 0; i < BAD_DESIRED_PRESENT_FRAMES; i++) {
974 mTimeStats->incrementBadDesiredPresent(LAYER_ID_0);
975 }
976 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
977
978 EXPECT_THAT(mDelegate->mAtomTags,
979 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
980 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
981 EXPECT_NE(nullptr, mDelegate->mCallback);
982 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
983
984 std::string expectedPresentToPresent = buildExpectedHistogramBytestring({1}, {1});
985 std::string expectedPostToPresent = buildExpectedHistogramBytestring({4}, {1});
986 std::string expectedAcquireToPresent = buildExpectedHistogramBytestring({3}, {1});
987 std::string expectedLatchToPresent = buildExpectedHistogramBytestring({2}, {1});
988 std::string expectedDesiredToPresent = buildExpectedHistogramBytestring({1}, {1});
989 std::string expectedPostToAcquire = buildExpectedHistogramBytestring({1}, {1});
990 {
991 InSequence seq;
992 EXPECT_CALL(*mDelegate,
993 statsEventSetAtomId(mDelegate->mEvent,
994 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
995 EXPECT_CALL(*mDelegate,
996 statsEventWriteString8(mDelegate->mEvent,
997 StrEq(genLayerName(LAYER_ID_0).c_str())));
998 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, 1));
999 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, 0));
1000 EXPECT_CALL(*mDelegate,
1001 statsEventWriteByteArray(mDelegate->mEvent,
1002 BytesEq((const uint8_t*)
1003 expectedPresentToPresent.c_str(),
1004 expectedPresentToPresent.size()),
1005 expectedPresentToPresent.size()));
1006 EXPECT_CALL(*mDelegate,
1007 statsEventWriteByteArray(mDelegate->mEvent,
1008 BytesEq((const uint8_t*)expectedPostToPresent.c_str(),
1009 expectedPostToPresent.size()),
1010 expectedPostToPresent.size()));
1011 EXPECT_CALL(*mDelegate,
1012 statsEventWriteByteArray(mDelegate->mEvent,
1013 BytesEq((const uint8_t*)
1014 expectedAcquireToPresent.c_str(),
1015 expectedAcquireToPresent.size()),
1016 expectedAcquireToPresent.size()));
1017 EXPECT_CALL(*mDelegate,
1018 statsEventWriteByteArray(mDelegate->mEvent,
1019 BytesEq((const uint8_t*)expectedLatchToPresent.c_str(),
1020 expectedLatchToPresent.size()),
1021 expectedLatchToPresent.size()));
1022 EXPECT_CALL(*mDelegate,
1023 statsEventWriteByteArray(mDelegate->mEvent,
1024 BytesEq((const uint8_t*)
1025 expectedDesiredToPresent.c_str(),
1026 expectedDesiredToPresent.size()),
1027 expectedDesiredToPresent.size()));
1028 EXPECT_CALL(*mDelegate,
1029 statsEventWriteByteArray(mDelegate->mEvent,
1030 BytesEq((const uint8_t*)expectedPostToAcquire.c_str(),
1031 expectedPostToAcquire.size()),
1032 expectedPostToAcquire.size()));
1033 EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, LATE_ACQUIRE_FRAMES));
1034 EXPECT_CALL(*mDelegate,
1035 statsEventWriteInt64(mDelegate->mEvent, BAD_DESIRED_PRESENT_FRAMES));
1036 EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent));
1037 }
1038 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
1039 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
1040 mDelegate->mCookie));
1041
1042 SFTimeStatsGlobalProto globalProto;
1043 ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
1044
1045 EXPECT_EQ(0, globalProto.stats_size());
1046 }
1047
TEST_F(TimeStatsTest,layerStatsCallback_pullsMultipleLayers)1048 TEST_F(TimeStatsTest, layerStatsCallback_pullsMultipleLayers) {
1049 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
1050
1051 mTimeStats->onBootFinished();
1052
1053 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
1054 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
1055 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 1, 2000000);
1056 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 2, 3000000);
1057
1058 EXPECT_THAT(mDelegate->mAtomTags,
1059 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1060 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1061 EXPECT_NE(nullptr, mDelegate->mCallback);
1062 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
1063
1064 EXPECT_CALL(*mDelegate,
1065 statsEventSetAtomId(mDelegate->mEvent,
1066 android::util::SURFACEFLINGER_STATS_LAYER_INFO))
1067 .Times(2);
1068 EXPECT_CALL(*mDelegate,
1069 statsEventWriteString8(mDelegate->mEvent, StrEq(genLayerName(LAYER_ID_0).c_str())));
1070 EXPECT_CALL(*mDelegate,
1071 statsEventWriteString8(mDelegate->mEvent, StrEq(genLayerName(LAYER_ID_1).c_str())));
1072 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
1073 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
1074 mDelegate->mCookie));
1075 }
1076
TEST_F(TimeStatsTest,layerStatsCallback_pullsMultipleBuckets)1077 TEST_F(TimeStatsTest, layerStatsCallback_pullsMultipleBuckets) {
1078 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
1079
1080 mTimeStats->onBootFinished();
1081
1082 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
1083 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
1084 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 3, 4000000);
1085 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 4, 5000000);
1086
1087 // Now make sure that TimeStats flushes global stats to set the callback.
1088 mTimeStats->setPowerMode(PowerMode::ON);
1089 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(3000000));
1090 mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(5000000));
1091 EXPECT_THAT(mDelegate->mAtomTags,
1092 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1093 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1094 EXPECT_NE(nullptr, mDelegate->mCallback);
1095 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
1096
1097 EXPECT_THAT(mDelegate->mAtomTags,
1098 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1099 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1100 std::string expectedPresentToPresent = buildExpectedHistogramBytestring({1, 2}, {2, 1});
1101 {
1102 InSequence seq;
1103 EXPECT_CALL(*mDelegate,
1104 statsEventWriteByteArray(mDelegate->mEvent,
1105 BytesEq((const uint8_t*)
1106 expectedPresentToPresent.c_str(),
1107 expectedPresentToPresent.size()),
1108 expectedPresentToPresent.size()));
1109 EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, _, _))
1110 .Times(AnyNumber());
1111 }
1112 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
1113 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
1114 mDelegate->mCookie));
1115 }
1116
TEST_F(TimeStatsTest,layerStatsCallback_limitsHistogramBuckets)1117 TEST_F(TimeStatsTest, layerStatsCallback_limitsHistogramBuckets) {
1118 mDelegate = new FakeStatsEventDelegate;
1119 mTimeStats =
1120 std::make_unique<impl::TimeStats>(std::unique_ptr<FakeStatsEventDelegate>(mDelegate),
1121 std::nullopt, 1);
1122 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
1123
1124 mTimeStats->onBootFinished();
1125
1126 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
1127 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
1128 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 3, 4000000);
1129 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 4, 5000000);
1130
1131 EXPECT_THAT(mDelegate->mAtomTags,
1132 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1133 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1134 EXPECT_NE(nullptr, mDelegate->mCallback);
1135 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
1136
1137 EXPECT_THAT(mDelegate->mAtomTags,
1138 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1139 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1140 std::string expectedPresentToPresent = buildExpectedHistogramBytestring({1}, {2});
1141 {
1142 InSequence seq;
1143 EXPECT_CALL(*mDelegate,
1144 statsEventWriteByteArray(mDelegate->mEvent,
1145 BytesEq((const uint8_t*)
1146 expectedPresentToPresent.c_str(),
1147 expectedPresentToPresent.size()),
1148 expectedPresentToPresent.size()));
1149 EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, _, _))
1150 .Times(AnyNumber());
1151 }
1152 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
1153 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
1154 mDelegate->mCookie));
1155 }
1156
TEST_F(TimeStatsTest,layerStatsCallback_limitsLayers)1157 TEST_F(TimeStatsTest, layerStatsCallback_limitsLayers) {
1158 mDelegate = new FakeStatsEventDelegate;
1159 mTimeStats =
1160 std::make_unique<impl::TimeStats>(std::unique_ptr<FakeStatsEventDelegate>(mDelegate), 1,
1161 std::nullopt);
1162 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
1163
1164 mTimeStats->onBootFinished();
1165
1166 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
1167 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000);
1168 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 1, 2000000);
1169 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 2, 3000000);
1170 insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_1, 4, 5000000);
1171
1172 EXPECT_THAT(mDelegate->mAtomTags,
1173 UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
1174 android::util::SURFACEFLINGER_STATS_LAYER_INFO));
1175 EXPECT_NE(nullptr, mDelegate->mCallback);
1176 EXPECT_EQ(mTimeStats.get(), mDelegate->mCookie);
1177
1178 EXPECT_CALL(*mDelegate,
1179 statsEventSetAtomId(mDelegate->mEvent,
1180 android::util::SURFACEFLINGER_STATS_LAYER_INFO))
1181 .Times(1);
1182 EXPECT_CALL(*mDelegate,
1183 statsEventWriteString8(mDelegate->mEvent, StrEq(genLayerName(LAYER_ID_1).c_str())));
1184 EXPECT_EQ(AStatsManager_PULL_SUCCESS,
1185 mDelegate->makePullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
1186 mDelegate->mCookie));
1187 }
1188
TEST_F(TimeStatsTest,canSurviveMonkey)1189 TEST_F(TimeStatsTest, canSurviveMonkey) {
1190 if (g_noSlowTests) {
1191 GTEST_SKIP();
1192 }
1193
1194 EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
1195
1196 for (size_t i = 0; i < 10000000; ++i) {
1197 const int32_t layerId = genRandomInt32(-1, 10);
1198 const int32_t frameNumber = genRandomInt32(1, 10);
1199 switch (genRandomInt32(0, 100)) {
1200 case 0:
1201 ALOGV("removeTimeRecord");
1202 ASSERT_NO_FATAL_FAILURE(mTimeStats->removeTimeRecord(layerId, frameNumber));
1203 continue;
1204 case 1:
1205 ALOGV("onDestroy");
1206 ASSERT_NO_FATAL_FAILURE(mTimeStats->onDestroy(layerId));
1207 continue;
1208 }
1209 TimeStamp type = static_cast<TimeStamp>(genRandomInt32(TIME_STAMP_BEGIN, TIME_STAMP_END));
1210 const int32_t ts = genRandomInt32(1, 1000000000);
1211 ALOGV("type[%d], layerId[%d], frameNumber[%d], ts[%d]", type, layerId, frameNumber, ts);
1212 setTimeStamp(type, layerId, frameNumber, ts);
1213 }
1214 }
1215
1216 } // namespace
1217 } // namespace android
1218
1219 // TODO(b/129481165): remove the #pragma below and fix conversion issues
1220 #pragma clang diagnostic pop // ignored "-Wconversion"
1221