blob: 1895777f7cd6e9ffa026b6b35a561e2c24c8948a [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>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070023#include <log/log.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070024#include <utils/String8.h>
Yiwei Zhang3a226d22018-10-16 09:23:03 -070025#include <utils/Timers.h>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070026#include <utils/Trace.h>
27
28#include <algorithm>
Alec Mouri9519bf12019-11-15 16:54:44 -080029#include <chrono>
Yiwei Zhang0102ad22018-05-02 17:37:17 -070030
31namespace android {
32
Alec Mourifb571ea2019-01-24 18:42:10 -080033namespace impl {
34
Alec Mourib3885ad2019-09-06 17:08:55 -070035TimeStats::TimeStats() {
36 // Temporarily enable TimeStats by default. Telemetry is disabled while
37 // we move onto statsd, so TimeStats is currently not exercised at all
38 // during testing.
39 // TODO: remove this.
40 enable();
41}
42
Dominik Laskowskic2867142019-01-21 11:33:38 -080043void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070044 ATRACE_CALL();
45
Yiwei Zhang0102ad22018-05-02 17:37:17 -070046 std::unordered_map<std::string, int32_t> argsMap;
Dominik Laskowskic2867142019-01-21 11:33:38 -080047 for (size_t index = 0; index < args.size(); ++index) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070048 argsMap[std::string(String8(args[index]).c_str())] = index;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070049 }
50
51 if (argsMap.count("-disable")) {
52 disable();
53 }
54
55 if (argsMap.count("-dump")) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070056 std::optional<uint32_t> maxLayers = std::nullopt;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070057 auto iter = argsMap.find("-maxlayers");
58 if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070059 int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
60 value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
61 maxLayers = static_cast<uint32_t>(value);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070062 }
63
Yiwei Zhang8a4015c2018-05-08 16:03:47 -070064 dump(asProto, maxLayers, result);
Yiwei Zhang0102ad22018-05-02 17:37:17 -070065 }
66
67 if (argsMap.count("-clear")) {
68 clear();
69 }
70
71 if (argsMap.count("-enable")) {
72 enable();
73 }
74}
75
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070076std::string TimeStats::miniDump() {
77 ATRACE_CALL();
78
79 std::string result = "TimeStats miniDump:\n";
80 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -070081 android::base::StringAppendF(&result, "Number of layers currently being tracked is %zu\n",
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070082 mTimeStatsTracker.size());
Yiwei Zhange926ab52019-08-14 15:16:00 -070083 android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
84 mTimeStats.stats.size());
Yiwei Zhang7eb58b72019-04-22 19:00:02 -070085 return result;
86}
87
Yiwei Zhang0102ad22018-05-02 17:37:17 -070088void TimeStats::incrementTotalFrames() {
89 if (!mEnabled.load()) return;
90
91 ATRACE_CALL();
92
93 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -070094 mTimeStats.totalFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -070095}
96
Yiwei Zhang621f9d42018-05-07 10:40:55 -070097void TimeStats::incrementMissedFrames() {
Yiwei Zhang0102ad22018-05-02 17:37:17 -070098 if (!mEnabled.load()) return;
99
100 ATRACE_CALL();
101
102 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700103 mTimeStats.missedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700104}
105
106void TimeStats::incrementClientCompositionFrames() {
107 if (!mEnabled.load()) return;
108
109 ATRACE_CALL();
110
111 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700112 mTimeStats.clientCompositionFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700113}
114
Alec Mouri9519bf12019-11-15 16:54:44 -0800115static int32_t msBetween(nsecs_t start, nsecs_t end) {
116 int64_t delta = std::chrono::duration_cast<std::chrono::milliseconds>(
117 std::chrono::nanoseconds(end - start))
118 .count();
119 delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
120 return static_cast<int32_t>(delta);
121}
122
123void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
124 if (!mEnabled.load()) return;
125
126 std::lock_guard<std::mutex> lock(mMutex);
127 if (mPowerTime.powerMode == HWC_POWER_MODE_NORMAL) {
128 mTimeStats.frameDuration.insert(msBetween(startTime, endTime));
129 }
130}
131
Alec Mourie4034bb2019-11-19 12:45:54 -0800132void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) {
133 if (!mEnabled.load()) return;
134
135 std::lock_guard<std::mutex> lock(mMutex);
136 if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
137 ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
138 mGlobalRecord.renderEngineDurations.pop_front();
139 }
140 mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
141}
142
143void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
144 const std::shared_ptr<FenceTime>& endTime) {
145 if (!mEnabled.load()) return;
146
147 std::lock_guard<std::mutex> lock(mMutex);
148 if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
149 ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
150 mGlobalRecord.renderEngineDurations.pop_front();
151 }
152 mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
153}
154
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800155bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700156 if (!timeRecord->ready) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800157 ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700158 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700159 return false;
160 }
161
162 if (timeRecord->acquireFence != nullptr) {
163 if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
164 return false;
165 }
166 if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700167 timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700168 timeRecord->acquireFence = nullptr;
169 } else {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800170 ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700171 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700172 }
173 }
174
175 if (timeRecord->presentFence != nullptr) {
176 if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
177 return false;
178 }
179 if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700180 timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700181 timeRecord->presentFence = nullptr;
182 } else {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800183 ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700184 timeRecord->frameTime.frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700185 }
186 }
187
188 return true;
189}
190
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800191void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700192 ATRACE_CALL();
193
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800194 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700195 TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700196 std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700197 while (!timeRecords.empty()) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800198 if (!recordReadyLocked(layerId, &timeRecords[0])) break;
199 ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700200 timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700201
202 if (prevTimeRecord.ready) {
Yiwei Zhangeafa5cc2019-07-26 15:06:25 -0700203 const std::string& layerName = layerRecord.layerName;
Yiwei Zhangdc224042018-10-18 15:34:00 -0700204 if (!mTimeStats.stats.count(layerName)) {
205 mTimeStats.stats[layerName].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700206 }
Yiwei Zhangdc224042018-10-18 15:34:00 -0700207 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700208 timeStatsLayer.totalFrames++;
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700209 timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
210 layerRecord.droppedFrames = 0;
211
212 const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
213 timeRecords[0].frameTime.acquireTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800214 ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerId,
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700215 timeRecords[0].frameTime.frameNumber, postToAcquireMs);
216 timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700217
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700218 const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
219 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800220 ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700221 timeRecords[0].frameTime.frameNumber, postToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700222 timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
223
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700224 const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
225 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800226 ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700227 timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700228 timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
229
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700230 const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
231 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800232 ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700233 timeRecords[0].frameTime.frameNumber, latchToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700234 timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
235
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700236 const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
237 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800238 ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700239 timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700240 timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
241
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700242 const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
243 timeRecords[0].frameTime.presentTime);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800244 ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerId,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700245 timeRecords[0].frameTime.frameNumber, presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700246 timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700247 }
248 prevTimeRecord = timeRecords[0];
Yiwei Zhangc5f2c452018-05-08 16:31:56 -0700249 timeRecords.pop_front();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700250 layerRecord.waitData--;
251 }
252}
253
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700254static constexpr const char* kPopupWindowPrefix = "PopupWindow";
255static const size_t kMinLenLayerName = std::strlen(kPopupWindowPrefix);
Yiwei Zhangbd408322018-10-15 18:31:53 -0700256
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700257// Avoid tracking the "PopupWindow:<random hash>#<number>" layers
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700258static bool layerNameIsValid(const std::string& layerName) {
Yiwei Zhang8bec7e82019-10-07 18:08:26 -0700259 return layerName.length() >= kMinLenLayerName &&
260 layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700261}
262
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800263void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700264 nsecs_t postTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700265 if (!mEnabled.load()) return;
266
267 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800268 ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(),
Yiwei Zhang8e8fe522018-11-02 18:34:07 -0700269 postTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700270
271 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange926ab52019-08-14 15:16:00 -0700272 if (!mTimeStats.stats.count(layerName) && mTimeStats.stats.size() >= MAX_NUM_LAYER_STATS) {
273 return;
274 }
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800275 if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
Yiwei Zhang7eb58b72019-04-22 19:00:02 -0700276 layerNameIsValid(layerName)) {
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800277 mTimeStatsTracker[layerId].layerName = layerName;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700278 }
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800279 if (!mTimeStatsTracker.count(layerId)) return;
280 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700281 if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800282 ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800283 layerId, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
284 mTimeStatsTracker.erase(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700285 return;
286 }
287 // For most media content, the acquireFence is invalid because the buffer is
288 // ready at the queueBuffer stage. In this case, acquireTime should be given
289 // a default value as postTime.
290 TimeRecord timeRecord = {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700291 .frameTime =
292 {
293 .frameNumber = frameNumber,
294 .postTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800295 .latchTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700296 .acquireTime = postTime,
Yiwei Zhangaf8ee942018-11-22 00:15:23 -0800297 .desiredTime = postTime,
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700298 },
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700299 };
300 layerRecord.timeRecords.push_back(timeRecord);
301 if (layerRecord.waitData < 0 ||
302 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
303 layerRecord.waitData = layerRecord.timeRecords.size() - 1;
304}
305
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800306void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700307 if (!mEnabled.load()) return;
308
309 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800310 ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700311
312 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800313 if (!mTimeStatsTracker.count(layerId)) return;
314 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700315 if (layerRecord.waitData < 0 ||
316 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
317 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700318 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700319 if (timeRecord.frameTime.frameNumber == frameNumber) {
320 timeRecord.frameTime.latchTime = latchTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700321 }
322}
323
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800324void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700325 if (!mEnabled.load()) return;
326
327 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800328 ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700329
330 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800331 if (!mTimeStatsTracker.count(layerId)) return;
332 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700333 if (layerRecord.waitData < 0 ||
334 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
335 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700336 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700337 if (timeRecord.frameTime.frameNumber == frameNumber) {
338 timeRecord.frameTime.desiredTime = desiredTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700339 }
340}
341
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800342void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700343 if (!mEnabled.load()) return;
344
345 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800346 ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700347
348 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800349 if (!mTimeStatsTracker.count(layerId)) return;
350 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700351 if (layerRecord.waitData < 0 ||
352 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
353 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700354 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700355 if (timeRecord.frameTime.frameNumber == frameNumber) {
356 timeRecord.frameTime.acquireTime = acquireTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700357 }
358}
359
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800360void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700361 const std::shared_ptr<FenceTime>& acquireFence) {
362 if (!mEnabled.load()) return;
363
364 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800365 ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700366 acquireFence->getSignalTime());
367
368 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800369 if (!mTimeStatsTracker.count(layerId)) return;
370 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700371 if (layerRecord.waitData < 0 ||
372 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
373 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700374 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700375 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700376 timeRecord.acquireFence = acquireFence;
377 }
378}
379
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800380void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700381 if (!mEnabled.load()) return;
382
383 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800384 ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700385
386 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800387 if (!mTimeStatsTracker.count(layerId)) return;
388 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700389 if (layerRecord.waitData < 0 ||
390 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
391 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700392 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700393 if (timeRecord.frameTime.frameNumber == frameNumber) {
394 timeRecord.frameTime.presentTime = presentTime;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700395 timeRecord.ready = true;
396 layerRecord.waitData++;
397 }
398
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800399 flushAvailableRecordsToStatsLocked(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700400}
401
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800402void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700403 const std::shared_ptr<FenceTime>& presentFence) {
404 if (!mEnabled.load()) return;
405
406 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800407 ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber,
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700408 presentFence->getSignalTime());
409
410 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800411 if (!mTimeStatsTracker.count(layerId)) return;
412 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhangcb7dd002019-04-16 11:03:01 -0700413 if (layerRecord.waitData < 0 ||
414 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
415 return;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700416 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700417 if (timeRecord.frameTime.frameNumber == frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700418 timeRecord.presentFence = presentFence;
419 timeRecord.ready = true;
420 layerRecord.waitData++;
421 }
422
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800423 flushAvailableRecordsToStatsLocked(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700424}
425
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800426void TimeStats::onDestroy(int32_t layerId) {
Yiwei Zhangdc224042018-10-18 15:34:00 -0700427 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800428 ALOGV("[%d]-onDestroy", layerId);
Mikael Pessa90092f42019-08-26 17:22:04 -0700429 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800430 mTimeStatsTracker.erase(layerId);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700431}
432
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800433void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700434 if (!mEnabled.load()) return;
435
436 ATRACE_CALL();
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800437 ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700438
439 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang1a88c402019-11-18 10:43:58 -0800440 if (!mTimeStatsTracker.count(layerId)) return;
441 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700442 size_t removeAt = 0;
443 for (const TimeRecord& record : layerRecord.timeRecords) {
Yiwei Zhangcf50ab92018-06-14 10:50:12 -0700444 if (record.frameTime.frameNumber == frameNumber) break;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700445 removeAt++;
446 }
447 if (removeAt == layerRecord.timeRecords.size()) return;
448 layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
449 if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700450 layerRecord.waitData--;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700451 }
Yiwei Zhangeaeea062018-06-28 14:46:51 -0700452 layerRecord.droppedFrames++;
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700453}
454
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700455void TimeStats::flushPowerTimeLocked() {
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700456 if (!mEnabled.load()) return;
457
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700458 nsecs_t curTime = systemTime();
459 // elapsedTime is in milliseconds.
460 int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
461
462 switch (mPowerTime.powerMode) {
463 case HWC_POWER_MODE_NORMAL:
464 mTimeStats.displayOnTime += elapsedTime;
465 break;
466 case HWC_POWER_MODE_OFF:
467 case HWC_POWER_MODE_DOZE:
468 case HWC_POWER_MODE_DOZE_SUSPEND:
469 default:
470 break;
471 }
472
473 mPowerTime.prevTime = curTime;
474}
475
476void TimeStats::setPowerMode(int32_t powerMode) {
477 if (!mEnabled.load()) {
478 std::lock_guard<std::mutex> lock(mMutex);
479 mPowerTime.powerMode = powerMode;
480 return;
481 }
482
483 std::lock_guard<std::mutex> lock(mMutex);
484 if (powerMode == mPowerTime.powerMode) return;
485
486 flushPowerTimeLocked();
487 mPowerTime.powerMode = powerMode;
488}
489
Alec Mourifb571ea2019-01-24 18:42:10 -0800490void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
491 std::lock_guard<std::mutex> lock(mMutex);
492 if (mTimeStats.refreshRateStats.count(fps)) {
493 mTimeStats.refreshRateStats[fps] += duration;
494 } else {
495 mTimeStats.refreshRateStats.insert({fps, duration});
496 }
497}
498
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700499void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
500 ATRACE_CALL();
501
502 while (!mGlobalRecord.presentFences.empty()) {
503 const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
504 if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
505
506 if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
507 ALOGE("GlobalPresentFence is invalid!");
508 mGlobalRecord.prevPresentTime = 0;
509 mGlobalRecord.presentFences.pop_front();
510 continue;
511 }
512
513 ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
514 mGlobalRecord.presentFences.front()->getSignalTime());
515
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700516 if (mGlobalRecord.prevPresentTime != 0) {
517 const int32_t presentToPresentMs =
518 msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
519 ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
520 presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
521 mTimeStats.presentToPresent.insert(presentToPresentMs);
522 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700523
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700524 mGlobalRecord.prevPresentTime = curPresentTime;
525 mGlobalRecord.presentFences.pop_front();
526 }
Alec Mourie4034bb2019-11-19 12:45:54 -0800527 while (!mGlobalRecord.renderEngineDurations.empty()) {
528 const auto duration = mGlobalRecord.renderEngineDurations.front();
529 const auto& endTime = duration.endTime;
530
531 nsecs_t endNs = -1;
532
533 if (auto val = std::get_if<nsecs_t>(&endTime)) {
534 endNs = *val;
535 } else {
536 endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
537 }
538
539 if (endNs == Fence::SIGNAL_TIME_PENDING) break;
540
541 if (endNs < 0) {
542 ALOGE("RenderEngineTiming is invalid!");
543 mGlobalRecord.renderEngineDurations.pop_front();
544 continue;
545 }
546
547 const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
548 mTimeStats.renderEngineTiming.insert(renderEngineMs);
549
550 mGlobalRecord.renderEngineDurations.pop_front();
551 }
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700552}
553
554void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
555 if (!mEnabled.load()) return;
556
557 ATRACE_CALL();
558 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700559 if (presentFence == nullptr || !presentFence->isValid()) {
560 mGlobalRecord.prevPresentTime = 0;
561 return;
562 }
563
564 if (mPowerTime.powerMode != HWC_POWER_MODE_NORMAL) {
565 // Try flushing the last present fence on HWC_POWER_MODE_NORMAL.
566 flushAvailableGlobalRecordsToStatsLocked();
567 mGlobalRecord.presentFences.clear();
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700568 mGlobalRecord.prevPresentTime = 0;
569 return;
570 }
571
572 if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
573 // The front presentFence must be trapped in pending status in this
574 // case. Try dequeuing the front one to recover.
575 ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
576 mGlobalRecord.prevPresentTime = 0;
577 mGlobalRecord.presentFences.pop_front();
578 }
579
580 mGlobalRecord.presentFences.emplace_back(presentFence);
581 flushAvailableGlobalRecordsToStatsLocked();
582}
583
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700584void TimeStats::enable() {
585 if (mEnabled.load()) return;
586
587 ATRACE_CALL();
588
589 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700590 mEnabled.store(true);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700591 mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700592 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700593 ALOGD("Enabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700594}
595
596void TimeStats::disable() {
597 if (!mEnabled.load()) return;
598
599 ATRACE_CALL();
600
601 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700602 flushPowerTimeLocked();
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700603 mEnabled.store(false);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700604 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700605 ALOGD("Disabled");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700606}
607
608void TimeStats::clear() {
609 ATRACE_CALL();
610
611 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700612 mTimeStatsTracker.clear();
Yiwei Zhangdc224042018-10-18 15:34:00 -0700613 mTimeStats.stats.clear();
614 mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
615 mTimeStats.statsEnd = 0;
616 mTimeStats.totalFrames = 0;
617 mTimeStats.missedFrames = 0;
618 mTimeStats.clientCompositionFrames = 0;
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700619 mTimeStats.displayOnTime = 0;
Yiwei Zhangce6ebc02018-10-20 12:42:38 -0700620 mTimeStats.presentToPresent.hist.clear();
Alec Mourifb571ea2019-01-24 18:42:10 -0800621 mTimeStats.refreshRateStats.clear();
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700622 mPowerTime.prevTime = systemTime();
Yiwei Zhange5c49d52018-10-29 00:15:31 -0700623 mGlobalRecord.prevPresentTime = 0;
624 mGlobalRecord.presentFences.clear();
625 ALOGD("Cleared");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700626}
627
628bool TimeStats::isEnabled() {
629 return mEnabled.load();
630}
631
Yiwei Zhang5434a782018-12-05 18:06:32 -0800632void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700633 ATRACE_CALL();
634
635 std::lock_guard<std::mutex> lock(mMutex);
Yiwei Zhangdc224042018-10-18 15:34:00 -0700636 if (mTimeStats.statsStart == 0) {
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700637 return;
638 }
639
Yiwei Zhangdc224042018-10-18 15:34:00 -0700640 mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700641
Yiwei Zhang3a226d22018-10-16 09:23:03 -0700642 flushPowerTimeLocked();
643
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700644 if (asProto) {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700645 ALOGD("Dumping TimeStats as proto");
Yiwei Zhangdc224042018-10-18 15:34:00 -0700646 SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
Dominik Laskowski46470112019-08-02 13:13:11 -0700647 result.append(timeStatsProto.SerializeAsString());
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700648 } else {
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700649 ALOGD("Dumping TimeStats as text");
Yiwei Zhang5434a782018-12-05 18:06:32 -0800650 result.append(mTimeStats.toString(maxLayers));
Yiwei Zhang8a4015c2018-05-08 16:03:47 -0700651 result.append("\n");
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700652 }
653}
654
Alec Mourifb571ea2019-01-24 18:42:10 -0800655} // namespace impl
656
Yiwei Zhang0102ad22018-05-02 17:37:17 -0700657} // namespace android