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