blob: 3df8360a80d56b07b0cdbb149441eb14cc073759 [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
Alec Mourib3885ad2019-09-06 17:08:55 -070037TimeStats::TimeStats() {
38 // Temporarily enable TimeStats by default. Telemetry is disabled while
39 // we move onto statsd, so TimeStats is currently not exercised at all
40 // during testing.
41 // TODO: remove this.
42 enable();
43}
44
Dominik Laskowskic2867142019-01-21 11:33:38 -080045void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070046 ATRACE_CALL();
47
Yiwei Zhang0102ad22018-05-02 17:37:17 -070048 std::unordered_map<std::string, int32_t> argsMap;
Dominik Laskowskic2867142019-01-21 11:33:38 -080049 for (size_t index = 0; index < args.size(); ++index) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070050 argsMap[std::string(String8(args[index]).c_str())] = index;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070051 }
52
53 if (argsMap.count("-disable")) {
54 disable();
55 }
56
57 if (argsMap.count("-dump")) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070058 std::optional<uint32_t> maxLayers = std::nullopt;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070059 auto iter = argsMap.find("-maxlayers");
60 if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070061 int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
62 value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
63 maxLayers = static_cast<uint32_t>(value);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070064 }
65
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070066 dump(asProto, maxLayers, result);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070067 }
68
69 if (argsMap.count("-clear")) {
70 clear();
71 }
72
73 if (argsMap.count("-enable")) {
74 enable();
75 }
76}
77
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070078std::string TimeStats::miniDump() {
79 ATRACE_CALL();
80
81 std::string result = "TimeStats miniDump:\n";
82 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -070083 android::base::StringAppendF(&result, "Number of layers currently being tracked is %zu\n",
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070084 mTimeStatsTracker.size());
Yiwei Zhange926ab52019-08-14 15:16:00 -070085 android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
86 mTimeStats.stats.size());
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070087 return result;
88}
89
Yiwei Zhang0102ad22018-05-02 17:37:17 -070090void TimeStats::incrementTotalFrames() {
91 if (!mEnabled.load()) return;
92
93 ATRACE_CALL();
94
95 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -070096 mTimeStats.totalFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070097}
98
Yiwei Zhang621f9d42018-05-07 10:40:55 -070099void TimeStats::incrementMissedFrames() {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700100 if (!mEnabled.load()) return;
101
102 ATRACE_CALL();
103
104 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700105 mTimeStats.missedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700106}
107
108void TimeStats::incrementClientCompositionFrames() {
109 if (!mEnabled.load()) return;
110
111 ATRACE_CALL();
112
113 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700114 mTimeStats.clientCompositionFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700115}
116
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700117bool TimeStats::recordReadyLocked(int32_t layerID, TimeRecord* timeRecord) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700118 if (!timeRecord->ready) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700119 ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700120 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700121 return false;
122 }
123
124 if (timeRecord->acquireFence != nullptr) {
125 if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
126 return false;
127 }
128 if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700129 timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700130 timeRecord->acquireFence = nullptr;
131 } else {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700132 ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700133 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700134 }
135 }
136
137 if (timeRecord->presentFence != nullptr) {
138 if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
139 return false;
140 }
141 if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700142 timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700143 timeRecord->presentFence = nullptr;
144 } else {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700145 ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700146 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700147 }
148 }
149
150 return true;
151}
152
153static int32_t msBetween(nsecs_t start, nsecs_t end) {
154 int64_t delta = (end - start) / 1000000;
155 delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
156 return static_cast<int32_t>(delta);
157}
158
Yiwei Zhangbd408322018-10-15 18:31:53 -0700159// This regular expression captures the following for instance:
160// StatusBar in StatusBar#0
161// com.appname in com.appname/com.appname.activity#0
162// com.appname in SurfaceView - com.appname/com.appname.activity#0
163static const std::regex packageNameRegex("(?:SurfaceView[-\\s\\t]+)?([^/]+).*#\\d+");
164
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700165static std::string getPackageName(const std::string& layerName) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700166 std::smatch match;
Yiwei Zhangbd408322018-10-15 18:31:53 -0700167 if (std::regex_match(layerName.begin(), layerName.end(), match, packageNameRegex)) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700168 // There must be a match for group 1 otherwise the whole string is not
169 // matched and the above will return false
170 return match[1];
171 }
172 return "";
173}
174
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700175void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerID) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700176 ATRACE_CALL();
177
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700178 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700179 TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700180 std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700181 while (!timeRecords.empty()) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700182 if (!recordReadyLocked(layerID, &timeRecords[0])) break;
183 ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700184 timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700185
186 if (prevTimeRecord.ready) {
Yiwei Zhangeafa5cc2019-07-26 15:06:25 -0700187 const std::string& layerName = layerRecord.layerName;
Yiwei Zhangdc224042018-10-18 15:34:00 -0700188 if (!mTimeStats.stats.count(layerName)) {
189 mTimeStats.stats[layerName].layerName = layerName;
190 mTimeStats.stats[layerName].packageName = getPackageName(layerName);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700191 }
Yiwei Zhangdc224042018-10-18 15:34:00 -0700192 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700193 timeStatsLayer.totalFrames++;
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700194 timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
195 layerRecord.droppedFrames = 0;
196
197 const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
198 timeRecords[0].frameTime.acquireTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700199 ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerID,
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700200 timeRecords[0].frameTime.frameNumber, postToAcquireMs);
201 timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700202
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700203 const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
204 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700205 ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700206 timeRecords[0].frameTime.frameNumber, postToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700207 timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
208
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700209 const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
210 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700211 ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700212 timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700213 timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
214
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700215 const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
216 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700217 ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700218 timeRecords[0].frameTime.frameNumber, latchToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700219 timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
220
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700221 const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
222 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700223 ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700224 timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700225 timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
226
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700227 const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
228 timeRecords[0].frameTime.presentTime);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700229 ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerID,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700230 timeRecords[0].frameTime.frameNumber, presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700231 timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700232 }
233 prevTimeRecord = timeRecords[0];
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700234 timeRecords.pop_front();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700235 layerRecord.waitData--;
236 }
237}
238
Yiwei Zhangbd408322018-10-15 18:31:53 -0700239// This regular expression captures the following layer names for instance:
240// 1) StatusBat#0
241// 2) NavigationBar#1
242// 3) co(m).*#0
243// 4) SurfaceView - co(m).*#0
244// Using [-\\s\t]+ for the conjunction part between SurfaceView and co(m).*
245// is a bit more robust in case there's a slight change.
246// The layer name would only consist of . / $ _ 0-9 a-z A-Z in most cases.
247static const std::regex layerNameRegex(
248 "(((SurfaceView[-\\s\\t]+)?com?\\.[./$\\w]+)|((Status|Navigation)Bar))#\\d+");
249
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700250static bool layerNameIsValid(const std::string& layerName) {
Yiwei Zhangbd408322018-10-15 18:31:53 -0700251 return std::regex_match(layerName.begin(), layerName.end(), layerNameRegex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700252}
253
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700254void TimeStats::setPostTime(int32_t layerID, uint64_t frameNumber, const std::string& layerName,
255 nsecs_t postTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700256 if (!mEnabled.load()) return;
257
258 ATRACE_CALL();
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700259 ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerID, frameNumber, layerName.c_str(),
260 postTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700261
262 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -0700263 if (!mTimeStats.stats.count(layerName) && mTimeStats.stats.size() >= MAX_NUM_LAYER_STATS) {
264 return;
265 }
Yiwei Zhang7eb58b72019-04-22 19:00:02 -0700266 if (!mTimeStatsTracker.count(layerID) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
267 layerNameIsValid(layerName)) {
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700268 mTimeStatsTracker[layerID].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700269 }
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700270 if (!mTimeStatsTracker.count(layerID)) return;
271 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700272 if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800273 ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700274 layerID, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800275 mTimeStatsTracker.erase(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700276 return;
277 }
278 // For most media content, the acquireFence is invalid because the buffer is
279 // ready at the queueBuffer stage. In this case, acquireTime should be given
280 // a default value as postTime.
281 TimeRecord timeRecord = {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700282 .frameTime =
283 {
284 .frameNumber = frameNumber,
285 .postTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800286 .latchTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700287 .acquireTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800288 .desiredTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700289 },
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700290 };
291 layerRecord.timeRecords.push_back(timeRecord);
292 if (layerRecord.waitData < 0 ||
293 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
294 layerRecord.waitData = layerRecord.timeRecords.size() - 1;
295}
296
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700297void TimeStats::setLatchTime(int32_t layerID, uint64_t frameNumber, nsecs_t latchTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700298 if (!mEnabled.load()) return;
299
300 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700301 ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerID, frameNumber, latchTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700302
303 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700304 if (!mTimeStatsTracker.count(layerID)) return;
305 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700306 if (layerRecord.waitData < 0 ||
307 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
308 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700309 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700310 if (timeRecord.frameTime.frameNumber == frameNumber) {
311 timeRecord.frameTime.latchTime = latchTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700312 }
313}
314
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700315void TimeStats::setDesiredTime(int32_t layerID, uint64_t frameNumber, nsecs_t desiredTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700316 if (!mEnabled.load()) return;
317
318 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700319 ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerID, frameNumber, desiredTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700320
321 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700322 if (!mTimeStatsTracker.count(layerID)) return;
323 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700324 if (layerRecord.waitData < 0 ||
325 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
326 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700327 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700328 if (timeRecord.frameTime.frameNumber == frameNumber) {
329 timeRecord.frameTime.desiredTime = desiredTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700330 }
331}
332
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700333void TimeStats::setAcquireTime(int32_t layerID, uint64_t frameNumber, nsecs_t acquireTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700334 if (!mEnabled.load()) return;
335
336 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700337 ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerID, frameNumber, acquireTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700338
339 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700340 if (!mTimeStatsTracker.count(layerID)) return;
341 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700342 if (layerRecord.waitData < 0 ||
343 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
344 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700345 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700346 if (timeRecord.frameTime.frameNumber == frameNumber) {
347 timeRecord.frameTime.acquireTime = acquireTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700348 }
349}
350
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700351void TimeStats::setAcquireFence(int32_t layerID, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700352 const std::shared_ptr<FenceTime>& acquireFence) {
353 if (!mEnabled.load()) return;
354
355 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700356 ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerID, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700357 acquireFence->getSignalTime());
358
359 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700360 if (!mTimeStatsTracker.count(layerID)) return;
361 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700362 if (layerRecord.waitData < 0 ||
363 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
364 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700365 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700366 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700367 timeRecord.acquireFence = acquireFence;
368 }
369}
370
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700371void TimeStats::setPresentTime(int32_t layerID, uint64_t frameNumber, nsecs_t presentTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700372 if (!mEnabled.load()) return;
373
374 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700375 ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerID, frameNumber, presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700376
377 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700378 if (!mTimeStatsTracker.count(layerID)) return;
379 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700380 if (layerRecord.waitData < 0 ||
381 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
382 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700383 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700384 if (timeRecord.frameTime.frameNumber == frameNumber) {
385 timeRecord.frameTime.presentTime = presentTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700386 timeRecord.ready = true;
387 layerRecord.waitData++;
388 }
389
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700390 flushAvailableRecordsToStatsLocked(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700391}
392
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700393void TimeStats::setPresentFence(int32_t layerID, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700394 const std::shared_ptr<FenceTime>& presentFence) {
395 if (!mEnabled.load()) return;
396
397 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700398 ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerID, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700399 presentFence->getSignalTime());
400
401 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700402 if (!mTimeStatsTracker.count(layerID)) return;
403 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700404 if (layerRecord.waitData < 0 ||
405 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
406 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700407 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700408 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700409 timeRecord.presentFence = presentFence;
410 timeRecord.ready = true;
411 layerRecord.waitData++;
412 }
413
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700414 flushAvailableRecordsToStatsLocked(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700415}
416
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700417void TimeStats::onDestroy(int32_t layerID) {
Yiwei Zhangdc224042018-10-18 15:34:00 -0700418 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700419 ALOGV("[%d]-onDestroy", layerID);
Mikael Pessa90092f42019-08-26 17:22:04 -0700420 std::lock_guard<std::mutex> lock(mMutex);
421 mTimeStatsTracker.erase(layerID);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700422}
423
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700424void TimeStats::removeTimeRecord(int32_t layerID, uint64_t frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700425 if (!mEnabled.load()) return;
426
427 ATRACE_CALL();
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700428 ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerID, frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700429
430 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang9689e2f2018-05-11 12:33:23 -0700431 if (!mTimeStatsTracker.count(layerID)) return;
432 LayerRecord& layerRecord = mTimeStatsTracker[layerID];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700433 size_t removeAt = 0;
434 for (const TimeRecord& record : layerRecord.timeRecords) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700435 if (record.frameTime.frameNumber == frameNumber) break;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700436 removeAt++;
437 }
438 if (removeAt == layerRecord.timeRecords.size()) return;
439 layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
440 if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700441 layerRecord.waitData--;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700442 }
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700443 layerRecord.droppedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700444}
445
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700446void TimeStats::flushPowerTimeLocked() {
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700447 if (!mEnabled.load()) return;
448
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700449 nsecs_t curTime = systemTime();
450 // elapsedTime is in milliseconds.
451 int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
452
453 switch (mPowerTime.powerMode) {
454 case HWC_POWER_MODE_NORMAL:
455 mTimeStats.displayOnTime += elapsedTime;
456 break;
457 case HWC_POWER_MODE_OFF:
458 case HWC_POWER_MODE_DOZE:
459 case HWC_POWER_MODE_DOZE_SUSPEND:
460 default:
461 break;
462 }
463
464 mPowerTime.prevTime = curTime;
465}
466
467void TimeStats::setPowerMode(int32_t powerMode) {
468 if (!mEnabled.load()) {
469 std::lock_guard<std::mutex> lock(mMutex);
470 mPowerTime.powerMode = powerMode;
471 return;
472 }
473
474 std::lock_guard<std::mutex> lock(mMutex);
475 if (powerMode == mPowerTime.powerMode) return;
476
477 flushPowerTimeLocked();
478 mPowerTime.powerMode = powerMode;
479}
480
Alec Mourifb571ea2019-01-24 18:42:10 -0800481void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
482 std::lock_guard<std::mutex> lock(mMutex);
483 if (mTimeStats.refreshRateStats.count(fps)) {
484 mTimeStats.refreshRateStats[fps] += duration;
485 } else {
486 mTimeStats.refreshRateStats.insert({fps, duration});
487 }
488}
489
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700490void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
491 ATRACE_CALL();
492
493 while (!mGlobalRecord.presentFences.empty()) {
494 const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
495 if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
496
497 if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
498 ALOGE("GlobalPresentFence is invalid!");
499 mGlobalRecord.prevPresentTime = 0;
500 mGlobalRecord.presentFences.pop_front();
501 continue;
502 }
503
504 ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
505 mGlobalRecord.presentFences.front()->getSignalTime());
506
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700507 if (mGlobalRecord.prevPresentTime != 0) {
508 const int32_t presentToPresentMs =
509 msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
510 ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
511 presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
512 mTimeStats.presentToPresent.insert(presentToPresentMs);
513 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700514
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700515 mGlobalRecord.prevPresentTime = curPresentTime;
516 mGlobalRecord.presentFences.pop_front();
517 }
518}
519
520void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
521 if (!mEnabled.load()) return;
522
523 ATRACE_CALL();
524 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700525 if (presentFence == nullptr || !presentFence->isValid()) {
526 mGlobalRecord.prevPresentTime = 0;
527 return;
528 }
529
530 if (mPowerTime.powerMode != HWC_POWER_MODE_NORMAL) {
531 // Try flushing the last present fence on HWC_POWER_MODE_NORMAL.
532 flushAvailableGlobalRecordsToStatsLocked();
533 mGlobalRecord.presentFences.clear();
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700534 mGlobalRecord.prevPresentTime = 0;
535 return;
536 }
537
538 if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
539 // The front presentFence must be trapped in pending status in this
540 // case. Try dequeuing the front one to recover.
541 ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
542 mGlobalRecord.prevPresentTime = 0;
543 mGlobalRecord.presentFences.pop_front();
544 }
545
546 mGlobalRecord.presentFences.emplace_back(presentFence);
547 flushAvailableGlobalRecordsToStatsLocked();
548}
549
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700550void TimeStats::enable() {
551 if (mEnabled.load()) return;
552
553 ATRACE_CALL();
554
555 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700556 mEnabled.store(true);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700557 mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700558 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700559 ALOGD("Enabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700560}
561
562void TimeStats::disable() {
563 if (!mEnabled.load()) return;
564
565 ATRACE_CALL();
566
567 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700568 flushPowerTimeLocked();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700569 mEnabled.store(false);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700570 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700571 ALOGD("Disabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700572}
573
574void TimeStats::clear() {
575 ATRACE_CALL();
576
577 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700578 mTimeStatsTracker.clear();
Yiwei Zhangdc224042018-10-18 15:34:00 -0700579 mTimeStats.stats.clear();
580 mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
581 mTimeStats.statsEnd = 0;
582 mTimeStats.totalFrames = 0;
583 mTimeStats.missedFrames = 0;
584 mTimeStats.clientCompositionFrames = 0;
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700585 mTimeStats.displayOnTime = 0;
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700586 mTimeStats.presentToPresent.hist.clear();
Alec Mourifb571ea2019-01-24 18:42:10 -0800587 mTimeStats.refreshRateStats.clear();
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700588 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700589 mGlobalRecord.prevPresentTime = 0;
590 mGlobalRecord.presentFences.clear();
591 ALOGD("Cleared");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700592}
593
594bool TimeStats::isEnabled() {
595 return mEnabled.load();
596}
597
Yiwei Zhang5434a782018-12-05 18:06:32 -0800598void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700599 ATRACE_CALL();
600
601 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700602 if (mTimeStats.statsStart == 0) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700603 return;
604 }
605
Yiwei Zhangdc224042018-10-18 15:34:00 -0700606 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700607
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700608 flushPowerTimeLocked();
609
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700610 if (asProto) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700611 ALOGD("Dumping TimeStats as proto");
Yiwei Zhangdc224042018-10-18 15:34:00 -0700612 SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
Dominik Laskowski46470112019-08-02 13:13:11 -0700613 result.append(timeStatsProto.SerializeAsString());
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700614 } else {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700615 ALOGD("Dumping TimeStats as text");
Yiwei Zhang5434a782018-12-05 18:06:32 -0800616 result.append(mTimeStats.toString(maxLayers));
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700617 result.append("\n");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700618 }
619}
620
Alec Mourifb571ea2019-01-24 18:42:10 -0800621} // namespace impl
622
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700623} // namespace android