blob: 0939fa4f9b43bb45939adb29d05fd0cc73fbacca [file] [log] [blame]
Yiwei Zhang0102ad22018-05-02 17:37:17 -07001/*
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 */
Ady Abrahamb0dbdaa2020-01-06 16:19:42 -080016
17// TODO(b/129481165): remove the #pragma below and fix conversion issues
18#pragma clang diagnostic push
19#pragma clang diagnostic ignored "-Wconversion"
Yiwei Zhang0102ad22018-05-02 17:37:17 -070020#undef LOG_TAG
21#define LOG_TAG "TimeStats"
22#define ATRACE_TAG ATRACE_TAG_GRAPHICS
23
24#include "TimeStats.h"
25
26#include <android-base/stringprintf.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070027#include <log/log.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070028#include <utils/String8.h>
Yiwei Zhang3a226d22018-10-16 09:23:03 -070029#include <utils/Timers.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070030#include <utils/Trace.h>
31
32#include <algorithm>
Alec Mouri9519bf12019-11-15 16:54:44 -080033#include <chrono>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070034
35namespace android {
36
Alec Mourifb571ea2019-01-24 18:42:10 -080037namespace impl {
38
Alec Mourib3885ad2019-09-06 17:08:55 -070039TimeStats::TimeStats() {
40 // Temporarily enable TimeStats by default. Telemetry is disabled while
41 // we move onto statsd, so TimeStats is currently not exercised at all
42 // during testing.
43 // TODO: remove this.
44 enable();
45}
46
Dominik Laskowskic2867142019-01-21 11:33:38 -080047void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070048 ATRACE_CALL();
49
Yiwei Zhang0102ad22018-05-02 17:37:17 -070050 std::unordered_map<std::string, int32_t> argsMap;
Dominik Laskowskic2867142019-01-21 11:33:38 -080051 for (size_t index = 0; index < args.size(); ++index) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070052 argsMap[std::string(String8(args[index]).c_str())] = index;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070053 }
54
55 if (argsMap.count("-disable")) {
56 disable();
57 }
58
59 if (argsMap.count("-dump")) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070060 std::optional<uint32_t> maxLayers = std::nullopt;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070061 auto iter = argsMap.find("-maxlayers");
62 if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070063 int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
64 value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
65 maxLayers = static_cast<uint32_t>(value);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070066 }
67
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070068 dump(asProto, maxLayers, result);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070069 }
70
71 if (argsMap.count("-clear")) {
72 clear();
73 }
74
75 if (argsMap.count("-enable")) {
76 enable();
77 }
78}
79
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070080std::string TimeStats::miniDump() {
81 ATRACE_CALL();
82
83 std::string result = "TimeStats miniDump:\n";
84 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -070085 android::base::StringAppendF(&result, "Number of layers currently being tracked is %zu\n",
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070086 mTimeStatsTracker.size());
Yiwei Zhange926ab52019-08-14 15:16:00 -070087 android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
88 mTimeStats.stats.size());
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070089 return result;
90}
91
Yiwei Zhang0102ad22018-05-02 17:37:17 -070092void TimeStats::incrementTotalFrames() {
93 if (!mEnabled.load()) return;
94
95 ATRACE_CALL();
96
97 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -070098 mTimeStats.totalFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070099}
100
Yiwei Zhang621f9d42018-05-07 10:40:55 -0700101void TimeStats::incrementMissedFrames() {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700102 if (!mEnabled.load()) return;
103
104 ATRACE_CALL();
105
106 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700107 mTimeStats.missedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700108}
109
110void TimeStats::incrementClientCompositionFrames() {
111 if (!mEnabled.load()) return;
112
113 ATRACE_CALL();
114
115 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700116 mTimeStats.clientCompositionFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700117}
118
Alec Mouri9519bf12019-11-15 16:54:44 -0800119static int32_t msBetween(nsecs_t start, nsecs_t end) {
120 int64_t delta = std::chrono::duration_cast<std::chrono::milliseconds>(
121 std::chrono::nanoseconds(end - start))
122 .count();
123 delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
124 return static_cast<int32_t>(delta);
125}
126
127void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
128 if (!mEnabled.load()) return;
129
130 std::lock_guard<std::mutex> lock(mMutex);
131 if (mPowerTime.powerMode == HWC_POWER_MODE_NORMAL) {
132 mTimeStats.frameDuration.insert(msBetween(startTime, endTime));
133 }
134}
135
Alec Mourie4034bb2019-11-19 12:45:54 -0800136void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) {
137 if (!mEnabled.load()) return;
138
139 std::lock_guard<std::mutex> lock(mMutex);
140 if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
141 ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
142 mGlobalRecord.renderEngineDurations.pop_front();
143 }
144 mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
145}
146
147void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
148 const std::shared_ptr<FenceTime>& endTime) {
149 if (!mEnabled.load()) return;
150
151 std::lock_guard<std::mutex> lock(mMutex);
152 if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
153 ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
154 mGlobalRecord.renderEngineDurations.pop_front();
155 }
156 mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
157}
158
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800159bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700160 if (!timeRecord->ready) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800161 ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700162 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700163 return false;
164 }
165
166 if (timeRecord->acquireFence != nullptr) {
167 if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
168 return false;
169 }
170 if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700171 timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700172 timeRecord->acquireFence = nullptr;
173 } else {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800174 ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700175 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700176 }
177 }
178
179 if (timeRecord->presentFence != nullptr) {
180 if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
181 return false;
182 }
183 if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700184 timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700185 timeRecord->presentFence = nullptr;
186 } else {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800187 ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700188 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700189 }
190 }
191
192 return true;
193}
194
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800195void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700196 ATRACE_CALL();
197
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800198 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700199 TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700200 std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700201 while (!timeRecords.empty()) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800202 if (!recordReadyLocked(layerId, &timeRecords[0])) break;
203 ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700204 timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700205
206 if (prevTimeRecord.ready) {
Yiwei Zhangeafa5cc2019-07-26 15:06:25 -0700207 const std::string& layerName = layerRecord.layerName;
Yiwei Zhangdc224042018-10-18 15:34:00 -0700208 if (!mTimeStats.stats.count(layerName)) {
209 mTimeStats.stats[layerName].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700210 }
Yiwei Zhangdc224042018-10-18 15:34:00 -0700211 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700212 timeStatsLayer.totalFrames++;
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700213 timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
214 layerRecord.droppedFrames = 0;
215
216 const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
217 timeRecords[0].frameTime.acquireTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800218 ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerId,
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700219 timeRecords[0].frameTime.frameNumber, postToAcquireMs);
220 timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700221
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700222 const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
223 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800224 ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700225 timeRecords[0].frameTime.frameNumber, postToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700226 timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
227
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700228 const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
229 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800230 ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700231 timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700232 timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
233
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700234 const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
235 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800236 ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700237 timeRecords[0].frameTime.frameNumber, latchToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700238 timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
239
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700240 const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
241 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800242 ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700243 timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700244 timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
245
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700246 const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
247 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800248 ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700249 timeRecords[0].frameTime.frameNumber, presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700250 timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700251 }
252 prevTimeRecord = timeRecords[0];
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700253 timeRecords.pop_front();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700254 layerRecord.waitData--;
255 }
256}
257
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700258static constexpr const char* kPopupWindowPrefix = "PopupWindow";
259static const size_t kMinLenLayerName = std::strlen(kPopupWindowPrefix);
Yiwei Zhangbd408322018-10-15 18:31:53 -0700260
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700261// Avoid tracking the "PopupWindow:<random hash>#<number>" layers
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700262static bool layerNameIsValid(const std::string& layerName) {
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700263 return layerName.length() >= kMinLenLayerName &&
264 layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700265}
266
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800267void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700268 nsecs_t postTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700269 if (!mEnabled.load()) return;
270
271 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800272 ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(),
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700273 postTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700274
275 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -0700276 if (!mTimeStats.stats.count(layerName) && mTimeStats.stats.size() >= MAX_NUM_LAYER_STATS) {
277 return;
278 }
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800279 if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
Yiwei Zhang7eb58b72019-04-22 19:00:02 -0700280 layerNameIsValid(layerName)) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800281 mTimeStatsTracker[layerId].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700282 }
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800283 if (!mTimeStatsTracker.count(layerId)) return;
284 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700285 if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800286 ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800287 layerId, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
288 mTimeStatsTracker.erase(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700289 return;
290 }
291 // For most media content, the acquireFence is invalid because the buffer is
292 // ready at the queueBuffer stage. In this case, acquireTime should be given
293 // a default value as postTime.
294 TimeRecord timeRecord = {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700295 .frameTime =
296 {
297 .frameNumber = frameNumber,
298 .postTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800299 .latchTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700300 .acquireTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800301 .desiredTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700302 },
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700303 };
304 layerRecord.timeRecords.push_back(timeRecord);
305 if (layerRecord.waitData < 0 ||
306 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
307 layerRecord.waitData = layerRecord.timeRecords.size() - 1;
308}
309
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800310void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700311 if (!mEnabled.load()) return;
312
313 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800314 ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700315
316 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800317 if (!mTimeStatsTracker.count(layerId)) return;
318 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700319 if (layerRecord.waitData < 0 ||
320 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
321 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700322 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700323 if (timeRecord.frameTime.frameNumber == frameNumber) {
324 timeRecord.frameTime.latchTime = latchTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700325 }
326}
327
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800328void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700329 if (!mEnabled.load()) return;
330
331 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800332 ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700333
334 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800335 if (!mTimeStatsTracker.count(layerId)) return;
336 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700337 if (layerRecord.waitData < 0 ||
338 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
339 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700340 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700341 if (timeRecord.frameTime.frameNumber == frameNumber) {
342 timeRecord.frameTime.desiredTime = desiredTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700343 }
344}
345
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800346void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700347 if (!mEnabled.load()) return;
348
349 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800350 ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700351
352 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800353 if (!mTimeStatsTracker.count(layerId)) return;
354 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700355 if (layerRecord.waitData < 0 ||
356 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
357 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700358 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700359 if (timeRecord.frameTime.frameNumber == frameNumber) {
360 timeRecord.frameTime.acquireTime = acquireTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700361 }
362}
363
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800364void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700365 const std::shared_ptr<FenceTime>& acquireFence) {
366 if (!mEnabled.load()) return;
367
368 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800369 ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700370 acquireFence->getSignalTime());
371
372 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800373 if (!mTimeStatsTracker.count(layerId)) return;
374 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700375 if (layerRecord.waitData < 0 ||
376 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
377 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700378 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700379 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700380 timeRecord.acquireFence = acquireFence;
381 }
382}
383
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800384void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700385 if (!mEnabled.load()) return;
386
387 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800388 ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700389
390 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800391 if (!mTimeStatsTracker.count(layerId)) return;
392 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700393 if (layerRecord.waitData < 0 ||
394 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
395 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700396 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700397 if (timeRecord.frameTime.frameNumber == frameNumber) {
398 timeRecord.frameTime.presentTime = presentTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700399 timeRecord.ready = true;
400 layerRecord.waitData++;
401 }
402
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800403 flushAvailableRecordsToStatsLocked(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700404}
405
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800406void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700407 const std::shared_ptr<FenceTime>& presentFence) {
408 if (!mEnabled.load()) return;
409
410 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800411 ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700412 presentFence->getSignalTime());
413
414 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800415 if (!mTimeStatsTracker.count(layerId)) return;
416 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700417 if (layerRecord.waitData < 0 ||
418 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
419 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700420 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700421 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700422 timeRecord.presentFence = presentFence;
423 timeRecord.ready = true;
424 layerRecord.waitData++;
425 }
426
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800427 flushAvailableRecordsToStatsLocked(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700428}
429
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800430void TimeStats::onDestroy(int32_t layerId) {
Yiwei Zhangdc224042018-10-18 15:34:00 -0700431 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800432 ALOGV("[%d]-onDestroy", layerId);
Mikael Pessa90092f42019-08-26 17:22:04 -0700433 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800434 mTimeStatsTracker.erase(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700435}
436
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800437void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700438 if (!mEnabled.load()) return;
439
440 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800441 ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700442
443 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800444 if (!mTimeStatsTracker.count(layerId)) return;
445 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700446 size_t removeAt = 0;
447 for (const TimeRecord& record : layerRecord.timeRecords) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700448 if (record.frameTime.frameNumber == frameNumber) break;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700449 removeAt++;
450 }
451 if (removeAt == layerRecord.timeRecords.size()) return;
452 layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
453 if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700454 layerRecord.waitData--;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700455 }
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700456 layerRecord.droppedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700457}
458
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700459void TimeStats::flushPowerTimeLocked() {
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700460 if (!mEnabled.load()) return;
461
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700462 nsecs_t curTime = systemTime();
463 // elapsedTime is in milliseconds.
464 int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
465
466 switch (mPowerTime.powerMode) {
467 case HWC_POWER_MODE_NORMAL:
468 mTimeStats.displayOnTime += elapsedTime;
469 break;
470 case HWC_POWER_MODE_OFF:
471 case HWC_POWER_MODE_DOZE:
472 case HWC_POWER_MODE_DOZE_SUSPEND:
473 default:
474 break;
475 }
476
477 mPowerTime.prevTime = curTime;
478}
479
480void TimeStats::setPowerMode(int32_t powerMode) {
481 if (!mEnabled.load()) {
482 std::lock_guard<std::mutex> lock(mMutex);
483 mPowerTime.powerMode = powerMode;
484 return;
485 }
486
487 std::lock_guard<std::mutex> lock(mMutex);
488 if (powerMode == mPowerTime.powerMode) return;
489
490 flushPowerTimeLocked();
491 mPowerTime.powerMode = powerMode;
492}
493
Alec Mourifb571ea2019-01-24 18:42:10 -0800494void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
495 std::lock_guard<std::mutex> lock(mMutex);
496 if (mTimeStats.refreshRateStats.count(fps)) {
497 mTimeStats.refreshRateStats[fps] += duration;
498 } else {
499 mTimeStats.refreshRateStats.insert({fps, duration});
500 }
501}
502
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700503void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
504 ATRACE_CALL();
505
506 while (!mGlobalRecord.presentFences.empty()) {
507 const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
508 if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
509
510 if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
511 ALOGE("GlobalPresentFence is invalid!");
512 mGlobalRecord.prevPresentTime = 0;
513 mGlobalRecord.presentFences.pop_front();
514 continue;
515 }
516
517 ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
518 mGlobalRecord.presentFences.front()->getSignalTime());
519
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700520 if (mGlobalRecord.prevPresentTime != 0) {
521 const int32_t presentToPresentMs =
522 msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
523 ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
524 presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
525 mTimeStats.presentToPresent.insert(presentToPresentMs);
526 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700527
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700528 mGlobalRecord.prevPresentTime = curPresentTime;
529 mGlobalRecord.presentFences.pop_front();
530 }
Alec Mourie4034bb2019-11-19 12:45:54 -0800531 while (!mGlobalRecord.renderEngineDurations.empty()) {
532 const auto duration = mGlobalRecord.renderEngineDurations.front();
533 const auto& endTime = duration.endTime;
534
535 nsecs_t endNs = -1;
536
537 if (auto val = std::get_if<nsecs_t>(&endTime)) {
538 endNs = *val;
539 } else {
540 endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
541 }
542
543 if (endNs == Fence::SIGNAL_TIME_PENDING) break;
544
545 if (endNs < 0) {
546 ALOGE("RenderEngineTiming is invalid!");
547 mGlobalRecord.renderEngineDurations.pop_front();
548 continue;
549 }
550
551 const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
552 mTimeStats.renderEngineTiming.insert(renderEngineMs);
553
554 mGlobalRecord.renderEngineDurations.pop_front();
555 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700556}
557
558void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
559 if (!mEnabled.load()) return;
560
561 ATRACE_CALL();
562 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700563 if (presentFence == nullptr || !presentFence->isValid()) {
564 mGlobalRecord.prevPresentTime = 0;
565 return;
566 }
567
568 if (mPowerTime.powerMode != HWC_POWER_MODE_NORMAL) {
569 // Try flushing the last present fence on HWC_POWER_MODE_NORMAL.
570 flushAvailableGlobalRecordsToStatsLocked();
571 mGlobalRecord.presentFences.clear();
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700572 mGlobalRecord.prevPresentTime = 0;
573 return;
574 }
575
576 if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
577 // The front presentFence must be trapped in pending status in this
578 // case. Try dequeuing the front one to recover.
579 ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
580 mGlobalRecord.prevPresentTime = 0;
581 mGlobalRecord.presentFences.pop_front();
582 }
583
584 mGlobalRecord.presentFences.emplace_back(presentFence);
585 flushAvailableGlobalRecordsToStatsLocked();
586}
587
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700588void TimeStats::enable() {
589 if (mEnabled.load()) return;
590
591 ATRACE_CALL();
592
593 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700594 mEnabled.store(true);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700595 mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700596 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700597 ALOGD("Enabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700598}
599
600void TimeStats::disable() {
601 if (!mEnabled.load()) return;
602
603 ATRACE_CALL();
604
605 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700606 flushPowerTimeLocked();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700607 mEnabled.store(false);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700608 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700609 ALOGD("Disabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700610}
611
612void TimeStats::clear() {
613 ATRACE_CALL();
614
615 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700616 mTimeStatsTracker.clear();
Yiwei Zhangdc224042018-10-18 15:34:00 -0700617 mTimeStats.stats.clear();
618 mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
619 mTimeStats.statsEnd = 0;
620 mTimeStats.totalFrames = 0;
621 mTimeStats.missedFrames = 0;
622 mTimeStats.clientCompositionFrames = 0;
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700623 mTimeStats.displayOnTime = 0;
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700624 mTimeStats.presentToPresent.hist.clear();
Alec Mouri31ac64a2020-01-09 09:26:22 -0800625 mTimeStats.frameDuration.hist.clear();
626 mTimeStats.renderEngineTiming.hist.clear();
Alec Mourifb571ea2019-01-24 18:42:10 -0800627 mTimeStats.refreshRateStats.clear();
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700628 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700629 mGlobalRecord.prevPresentTime = 0;
630 mGlobalRecord.presentFences.clear();
631 ALOGD("Cleared");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700632}
633
634bool TimeStats::isEnabled() {
635 return mEnabled.load();
636}
637
Yiwei Zhang5434a782018-12-05 18:06:32 -0800638void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700639 ATRACE_CALL();
640
641 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700642 if (mTimeStats.statsStart == 0) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700643 return;
644 }
645
Yiwei Zhangdc224042018-10-18 15:34:00 -0700646 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700647
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700648 flushPowerTimeLocked();
649
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700650 if (asProto) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700651 ALOGD("Dumping TimeStats as proto");
Yiwei Zhangdc224042018-10-18 15:34:00 -0700652 SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
Dominik Laskowski46470112019-08-02 13:13:11 -0700653 result.append(timeStatsProto.SerializeAsString());
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700654 } else {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700655 ALOGD("Dumping TimeStats as text");
Yiwei Zhang5434a782018-12-05 18:06:32 -0800656 result.append(mTimeStats.toString(maxLayers));
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700657 result.append("\n");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700658 }
659}
660
Alec Mourifb571ea2019-01-24 18:42:10 -0800661} // namespace impl
662
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700663} // namespace android
Ady Abrahamb0dbdaa2020-01-06 16:19:42 -0800664
665// TODO(b/129481165): remove the #pragma below and fix conversion issues
666#pragma clang diagnostic pop // ignored "-Wconversion"