blob: 887b7335326652b1b1b2937a65ee5f27585e913e [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 */
16#undef LOG_TAG
17#define LOG_TAG "TimeStats"
18#define ATRACE_TAG ATRACE_TAG_GRAPHICS
19
20#include "TimeStats.h"
21
22#include <android-base/stringprintf.h>
23
24#include <log/log.h>
25
26#include <utils/String8.h>
Yiwei Zhang3a226d22018-10-16 09:23:03 -070027#include <utils/Timers.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070028#include <utils/Trace.h>
29
30#include <algorithm>
31#include <regex>
32
33namespace android {
34
Alec Mourifb571ea2019-01-24 18:42:10 -080035namespace impl {
36
Dominik Laskowskic2867142019-01-21 11:33:38 -080037void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070038 ATRACE_CALL();
39
Yiwei Zhang0102ad22018-05-02 17:37:17 -070040 std::unordered_map<std::string, int32_t> argsMap;
Dominik Laskowskic2867142019-01-21 11:33:38 -080041 for (size_t index = 0; index < args.size(); ++index) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070042 argsMap[std::string(String8(args[index]).c_str())] = index;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070043 }
44
45 if (argsMap.count("-disable")) {
46 disable();
47 }
48
49 if (argsMap.count("-dump")) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070050 std::optional<uint32_t> maxLayers = std::nullopt;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070051 auto iter = argsMap.find("-maxlayers");
52 if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070053 int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
54 value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
55 maxLayers = static_cast<uint32_t>(value);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070056 }
57
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070058 dump(asProto, maxLayers, result);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070059 }
60
61 if (argsMap.count("-clear")) {
62 clear();
63 }
64
65 if (argsMap.count("-enable")) {
66 enable();
67 }
68}
69
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070070std::string TimeStats::miniDump() {
71 ATRACE_CALL();
72
73 std::string result = "TimeStats miniDump:\n";
74 std::lock_guard<std::mutex> lock(mMutex);
75 android::base::StringAppendF(&result, "Number of tracked layers is %zu\n",
76 mTimeStatsTracker.size());
77 return result;
78}
79
Yiwei Zhang0102ad22018-05-02 17:37:17 -070080void TimeStats::incrementTotalFrames() {
81 if (!mEnabled.load()) return;
82
83 ATRACE_CALL();
84
85 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -070086 mTimeStats.totalFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070087}
88
Yiwei Zhang621f9d42018-05-07 10:40:55 -070089void TimeStats::incrementMissedFrames() {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070090 if (!mEnabled.load()) return;
91
92 ATRACE_CALL();
93
94 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -070095 mTimeStats.missedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070096}
97
98void TimeStats::incrementClientCompositionFrames() {
99 if (!mEnabled.load()) return;
100
101 ATRACE_CALL();
102
103 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700104 mTimeStats.clientCompositionFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700105}
106
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700107bool TimeStats::recordReadyLocked(int32_t layerID, TimeRecord* timeRecord) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700108 if (!timeRecord->ready) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700109 ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700110 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700111 return false;
112 }
113
114 if (timeRecord->acquireFence != nullptr) {
115 if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
116 return false;
117 }
118 if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700119 timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700120 timeRecord->acquireFence = nullptr;
121 } else {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700122 ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700123 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700124 }
125 }
126
127 if (timeRecord->presentFence != nullptr) {
128 if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
129 return false;
130 }
131 if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700132 timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700133 timeRecord->presentFence = nullptr;
134 } else {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700135 ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700136 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700137 }
138 }
139
140 return true;
141}
142
143static int32_t msBetween(nsecs_t start, nsecs_t end) {
144 int64_t delta = (end - start) / 1000000;
145 delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
146 return static_cast<int32_t>(delta);
147}
148
Yiwei Zhangbd408322018-10-15 18:31:53 -0700149// This regular expression captures the following for instance:
150// StatusBar in StatusBar#0
151// com.appname in com.appname/com.appname.activity#0
152// com.appname in SurfaceView - com.appname/com.appname.activity#0
153static const std::regex packageNameRegex("(?:SurfaceView[-\\s\\t]+)?([^/]+).*#\\d+");
154
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700155static std::string getPackageName(const std::string& layerName) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700156 std::smatch match;
Yiwei Zhangbd408322018-10-15 18:31:53 -0700157 if (std::regex_match(layerName.begin(), layerName.end(), match, packageNameRegex)) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700158 // There must be a match for group 1 otherwise the whole string is not
159 // matched and the above will return false
160 return match[1];
161 }
162 return "";
163}
164
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700165void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerID) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700166 ATRACE_CALL();
167
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700168 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700169 TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700170 std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700171 while (!timeRecords.empty()) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700172 if (!recordReadyLocked(layerID, &timeRecords[0])) break;
173 ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700174 timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700175
176 if (prevTimeRecord.ready) {
Yiwei Zhangeafa5cc2019-07-26 15:06:25 -0700177 const std::string& layerName = layerRecord.layerName;
Yiwei Zhangdc224042018-10-18 15:34:00 -0700178 if (!mTimeStats.stats.count(layerName)) {
179 mTimeStats.stats[layerName].layerName = layerName;
180 mTimeStats.stats[layerName].packageName = getPackageName(layerName);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700181 }
Yiwei Zhangdc224042018-10-18 15:34:00 -0700182 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700183 timeStatsLayer.totalFrames++;
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700184 timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
185 layerRecord.droppedFrames = 0;
186
187 const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
188 timeRecords[0].frameTime.acquireTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700189 ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerID,
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700190 timeRecords[0].frameTime.frameNumber, postToAcquireMs);
191 timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700192
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700193 const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
194 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700195 ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700196 timeRecords[0].frameTime.frameNumber, postToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700197 timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
198
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700199 const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
200 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700201 ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700202 timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700203 timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
204
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700205 const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
206 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700207 ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700208 timeRecords[0].frameTime.frameNumber, latchToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700209 timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
210
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700211 const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
212 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700213 ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700214 timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700215 timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
216
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700217 const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
218 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700219 ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700220 timeRecords[0].frameTime.frameNumber, presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700221 timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700222 }
223 prevTimeRecord = timeRecords[0];
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700224 timeRecords.pop_front();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700225 layerRecord.waitData--;
226 }
227}
228
Yiwei Zhangbd408322018-10-15 18:31:53 -0700229// This regular expression captures the following layer names for instance:
230// 1) StatusBat#0
231// 2) NavigationBar#1
232// 3) co(m).*#0
233// 4) SurfaceView - co(m).*#0
234// Using [-\\s\t]+ for the conjunction part between SurfaceView and co(m).*
235// is a bit more robust in case there's a slight change.
236// The layer name would only consist of . / $ _ 0-9 a-z A-Z in most cases.
237static const std::regex layerNameRegex(
238 "(((SurfaceView[-\\s\\t]+)?com?\\.[./$\\w]+)|((Status|Navigation)Bar))#\\d+");
239
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700240static bool layerNameIsValid(const std::string& layerName) {
Yiwei Zhangbd408322018-10-15 18:31:53 -0700241 return std::regex_match(layerName.begin(), layerName.end(), layerNameRegex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700242}
243
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700244void TimeStats::setPostTime(int32_t layerID, uint64_t frameNumber, const std::string& layerName,
245 nsecs_t postTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700246 if (!mEnabled.load()) return;
247
248 ATRACE_CALL();
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700249 ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerID, frameNumber, layerName.c_str(),
250 postTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700251
252 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang7eb58b72019-04-22 19:00:02 -0700253 if (!mTimeStatsTracker.count(layerID) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
254 layerNameIsValid(layerName)) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700255 mTimeStatsTracker[layerID].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700256 }
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700257 if (!mTimeStatsTracker.count(layerID)) return;
258 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700259 if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800260 ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700261 layerID, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800262 mTimeStatsTracker.erase(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700263 return;
264 }
265 // For most media content, the acquireFence is invalid because the buffer is
266 // ready at the queueBuffer stage. In this case, acquireTime should be given
267 // a default value as postTime.
268 TimeRecord timeRecord = {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700269 .frameTime =
270 {
271 .frameNumber = frameNumber,
272 .postTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800273 .latchTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700274 .acquireTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800275 .desiredTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700276 },
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700277 };
278 layerRecord.timeRecords.push_back(timeRecord);
279 if (layerRecord.waitData < 0 ||
280 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
281 layerRecord.waitData = layerRecord.timeRecords.size() - 1;
282}
283
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700284void TimeStats::setLatchTime(int32_t layerID, uint64_t frameNumber, nsecs_t latchTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700285 if (!mEnabled.load()) return;
286
287 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700288 ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerID, frameNumber, latchTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700289
290 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700291 if (!mTimeStatsTracker.count(layerID)) return;
292 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700293 if (layerRecord.waitData < 0 ||
294 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
295 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700296 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700297 if (timeRecord.frameTime.frameNumber == frameNumber) {
298 timeRecord.frameTime.latchTime = latchTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700299 }
300}
301
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700302void TimeStats::setDesiredTime(int32_t layerID, uint64_t frameNumber, nsecs_t desiredTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700303 if (!mEnabled.load()) return;
304
305 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700306 ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerID, frameNumber, desiredTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700307
308 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700309 if (!mTimeStatsTracker.count(layerID)) return;
310 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700311 if (layerRecord.waitData < 0 ||
312 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
313 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700314 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700315 if (timeRecord.frameTime.frameNumber == frameNumber) {
316 timeRecord.frameTime.desiredTime = desiredTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700317 }
318}
319
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700320void TimeStats::setAcquireTime(int32_t layerID, uint64_t frameNumber, nsecs_t acquireTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700321 if (!mEnabled.load()) return;
322
323 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700324 ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerID, frameNumber, acquireTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700325
326 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700327 if (!mTimeStatsTracker.count(layerID)) return;
328 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700329 if (layerRecord.waitData < 0 ||
330 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
331 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700332 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700333 if (timeRecord.frameTime.frameNumber == frameNumber) {
334 timeRecord.frameTime.acquireTime = acquireTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700335 }
336}
337
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700338void TimeStats::setAcquireFence(int32_t layerID, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700339 const std::shared_ptr<FenceTime>& acquireFence) {
340 if (!mEnabled.load()) return;
341
342 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700343 ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerID, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700344 acquireFence->getSignalTime());
345
346 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700347 if (!mTimeStatsTracker.count(layerID)) return;
348 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700349 if (layerRecord.waitData < 0 ||
350 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
351 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700352 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700353 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700354 timeRecord.acquireFence = acquireFence;
355 }
356}
357
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700358void TimeStats::setPresentTime(int32_t layerID, uint64_t frameNumber, nsecs_t presentTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700359 if (!mEnabled.load()) return;
360
361 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700362 ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerID, frameNumber, presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700363
364 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700365 if (!mTimeStatsTracker.count(layerID)) return;
366 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700367 if (layerRecord.waitData < 0 ||
368 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
369 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700370 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700371 if (timeRecord.frameTime.frameNumber == frameNumber) {
372 timeRecord.frameTime.presentTime = presentTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700373 timeRecord.ready = true;
374 layerRecord.waitData++;
375 }
376
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700377 flushAvailableRecordsToStatsLocked(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700378}
379
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700380void TimeStats::setPresentFence(int32_t layerID, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700381 const std::shared_ptr<FenceTime>& presentFence) {
382 if (!mEnabled.load()) return;
383
384 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700385 ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerID, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700386 presentFence->getSignalTime());
387
388 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700389 if (!mTimeStatsTracker.count(layerID)) return;
390 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700391 if (layerRecord.waitData < 0 ||
392 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
393 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700394 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700395 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700396 timeRecord.presentFence = presentFence;
397 timeRecord.ready = true;
398 layerRecord.waitData++;
399 }
400
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700401 flushAvailableRecordsToStatsLocked(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700402}
403
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700404void TimeStats::onDestroy(int32_t layerID) {
Yiwei Zhangdc224042018-10-18 15:34:00 -0700405 if (!mEnabled.load()) return;
406
407 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700408 ALOGV("[%d]-onDestroy", layerID);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700409
410 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700411 if (!mTimeStatsTracker.count(layerID)) return;
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700412 mTimeStatsTracker.erase(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700413}
414
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700415void TimeStats::removeTimeRecord(int32_t layerID, uint64_t frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700416 if (!mEnabled.load()) return;
417
418 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700419 ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerID, frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700420
421 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700422 if (!mTimeStatsTracker.count(layerID)) return;
423 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700424 size_t removeAt = 0;
425 for (const TimeRecord& record : layerRecord.timeRecords) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700426 if (record.frameTime.frameNumber == frameNumber) break;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700427 removeAt++;
428 }
429 if (removeAt == layerRecord.timeRecords.size()) return;
430 layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
431 if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700432 layerRecord.waitData--;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700433 }
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700434 layerRecord.droppedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700435}
436
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700437void TimeStats::flushPowerTimeLocked() {
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700438 if (!mEnabled.load()) return;
439
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700440 nsecs_t curTime = systemTime();
441 // elapsedTime is in milliseconds.
442 int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
443
444 switch (mPowerTime.powerMode) {
445 case HWC_POWER_MODE_NORMAL:
446 mTimeStats.displayOnTime += elapsedTime;
447 break;
448 case HWC_POWER_MODE_OFF:
449 case HWC_POWER_MODE_DOZE:
450 case HWC_POWER_MODE_DOZE_SUSPEND:
451 default:
452 break;
453 }
454
455 mPowerTime.prevTime = curTime;
456}
457
458void TimeStats::setPowerMode(int32_t powerMode) {
459 if (!mEnabled.load()) {
460 std::lock_guard<std::mutex> lock(mMutex);
461 mPowerTime.powerMode = powerMode;
462 return;
463 }
464
465 std::lock_guard<std::mutex> lock(mMutex);
466 if (powerMode == mPowerTime.powerMode) return;
467
468 flushPowerTimeLocked();
469 mPowerTime.powerMode = powerMode;
470}
471
Alec Mourifb571ea2019-01-24 18:42:10 -0800472void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
473 std::lock_guard<std::mutex> lock(mMutex);
474 if (mTimeStats.refreshRateStats.count(fps)) {
475 mTimeStats.refreshRateStats[fps] += duration;
476 } else {
477 mTimeStats.refreshRateStats.insert({fps, duration});
478 }
479}
480
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700481void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
482 ATRACE_CALL();
483
484 while (!mGlobalRecord.presentFences.empty()) {
485 const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
486 if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
487
488 if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
489 ALOGE("GlobalPresentFence is invalid!");
490 mGlobalRecord.prevPresentTime = 0;
491 mGlobalRecord.presentFences.pop_front();
492 continue;
493 }
494
495 ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
496 mGlobalRecord.presentFences.front()->getSignalTime());
497
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700498 if (mGlobalRecord.prevPresentTime != 0) {
499 const int32_t presentToPresentMs =
500 msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
501 ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
502 presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
503 mTimeStats.presentToPresent.insert(presentToPresentMs);
504 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700505
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700506 mGlobalRecord.prevPresentTime = curPresentTime;
507 mGlobalRecord.presentFences.pop_front();
508 }
509}
510
511void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
512 if (!mEnabled.load()) return;
513
514 ATRACE_CALL();
515 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700516 if (presentFence == nullptr || !presentFence->isValid()) {
517 mGlobalRecord.prevPresentTime = 0;
518 return;
519 }
520
521 if (mPowerTime.powerMode != HWC_POWER_MODE_NORMAL) {
522 // Try flushing the last present fence on HWC_POWER_MODE_NORMAL.
523 flushAvailableGlobalRecordsToStatsLocked();
524 mGlobalRecord.presentFences.clear();
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700525 mGlobalRecord.prevPresentTime = 0;
526 return;
527 }
528
529 if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
530 // The front presentFence must be trapped in pending status in this
531 // case. Try dequeuing the front one to recover.
532 ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
533 mGlobalRecord.prevPresentTime = 0;
534 mGlobalRecord.presentFences.pop_front();
535 }
536
537 mGlobalRecord.presentFences.emplace_back(presentFence);
538 flushAvailableGlobalRecordsToStatsLocked();
539}
540
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700541void TimeStats::enable() {
542 if (mEnabled.load()) return;
543
544 ATRACE_CALL();
545
546 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700547 mEnabled.store(true);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700548 mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700549 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700550 ALOGD("Enabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700551}
552
553void TimeStats::disable() {
554 if (!mEnabled.load()) return;
555
556 ATRACE_CALL();
557
558 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700559 flushPowerTimeLocked();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700560 mEnabled.store(false);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700561 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700562 ALOGD("Disabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700563}
564
565void TimeStats::clear() {
566 ATRACE_CALL();
567
568 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700569 mTimeStatsTracker.clear();
Yiwei Zhangdc224042018-10-18 15:34:00 -0700570 mTimeStats.stats.clear();
571 mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
572 mTimeStats.statsEnd = 0;
573 mTimeStats.totalFrames = 0;
574 mTimeStats.missedFrames = 0;
575 mTimeStats.clientCompositionFrames = 0;
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700576 mTimeStats.displayOnTime = 0;
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700577 mTimeStats.presentToPresent.hist.clear();
Alec Mourifb571ea2019-01-24 18:42:10 -0800578 mTimeStats.refreshRateStats.clear();
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700579 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700580 mGlobalRecord.prevPresentTime = 0;
581 mGlobalRecord.presentFences.clear();
582 ALOGD("Cleared");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700583}
584
585bool TimeStats::isEnabled() {
586 return mEnabled.load();
587}
588
Yiwei Zhang5434a782018-12-05 18:06:32 -0800589void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700590 ATRACE_CALL();
591
592 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700593 if (mTimeStats.statsStart == 0) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700594 return;
595 }
596
Yiwei Zhangdc224042018-10-18 15:34:00 -0700597 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700598
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700599 flushPowerTimeLocked();
600
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700601 if (asProto) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700602 ALOGD("Dumping TimeStats as proto");
Yiwei Zhangdc224042018-10-18 15:34:00 -0700603 SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700604 result.append(timeStatsProto.SerializeAsString().c_str(), timeStatsProto.ByteSize());
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700605 } else {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700606 ALOGD("Dumping TimeStats as text");
Yiwei Zhang5434a782018-12-05 18:06:32 -0800607 result.append(mTimeStats.toString(maxLayers));
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700608 result.append("\n");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700609 }
610}
611
Alec Mourifb571ea2019-01-24 18:42:10 -0800612} // namespace impl
613
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700614} // namespace android