1 /*
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 
17 // TODO(b/129481165): remove the #pragma below and fix conversion issues
18 #pragma clang diagnostic push
19 #pragma clang diagnostic ignored "-Wconversion"
20 #undef LOG_TAG
21 #define LOG_TAG "TimeStats"
22 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
23 
24 #include "TimeStats.h"
25 
26 #include <android-base/stringprintf.h>
27 #include <android/util/ProtoOutputStream.h>
28 #include <log/log.h>
29 #include <utils/String8.h>
30 #include <utils/Timers.h>
31 #include <utils/Trace.h>
32 
33 #include <algorithm>
34 #include <chrono>
35 
36 namespace android {
37 
38 namespace impl {
39 
pullAtomCallback(int32_t atom_tag,AStatsEventList * data,void * cookie)40 AStatsManager_PullAtomCallbackReturn TimeStats::pullAtomCallback(int32_t atom_tag,
41                                                                  AStatsEventList* data,
42                                                                  void* cookie) {
43     impl::TimeStats* timeStats = reinterpret_cast<impl::TimeStats*>(cookie);
44     AStatsManager_PullAtomCallbackReturn result = AStatsManager_PULL_SKIP;
45     if (atom_tag == android::util::SURFACEFLINGER_STATS_GLOBAL_INFO) {
46         result = timeStats->populateGlobalAtom(data);
47     } else if (atom_tag == android::util::SURFACEFLINGER_STATS_LAYER_INFO) {
48         result = timeStats->populateLayerAtom(data);
49     }
50 
51     // Enable timestats now. The first full pull for a given build is expected to
52     // have empty or very little stats, as stats are first enabled after the
53     // first pull is completed for either the global or layer stats.
54     timeStats->enable();
55     return result;
56 }
57 
58 namespace {
59 // Histograms align with the order of fields in SurfaceflingerStatsLayerInfo.
60 const std::array<std::string, 6> kHistogramNames = {
61         "present2present", "post2present",    "acquire2present",
62         "latch2present",   "desired2present", "post2acquire",
63 };
64 
histogramToProtoByteString(const std::unordered_map<int32_t,int32_t> & histogram,size_t maxPulledHistogramBuckets)65 std::string histogramToProtoByteString(const std::unordered_map<int32_t, int32_t>& histogram,
66                                        size_t maxPulledHistogramBuckets) {
67     auto buckets = std::vector<std::pair<int32_t, int32_t>>(histogram.begin(), histogram.end());
68     std::sort(buckets.begin(), buckets.end(),
69               [](std::pair<int32_t, int32_t>& left, std::pair<int32_t, int32_t>& right) {
70                   return left.second > right.second;
71               });
72 
73     util::ProtoOutputStream proto;
74     int histogramSize = 0;
75     for (const auto& bucket : buckets) {
76         if (++histogramSize > maxPulledHistogramBuckets) {
77             break;
78         }
79         proto.write(android::util::FIELD_TYPE_INT32 | android::util::FIELD_COUNT_REPEATED |
80                             1 /* field id */,
81                     (int32_t)bucket.first);
82         proto.write(android::util::FIELD_TYPE_INT64 | android::util::FIELD_COUNT_REPEATED |
83                             2 /* field id */,
84                     (int64_t)bucket.second);
85     }
86 
87     std::string byteString;
88     proto.serializeToString(&byteString);
89     return byteString;
90 }
91 } // namespace
92 
populateGlobalAtom(AStatsEventList * data)93 AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventList* data) {
94     std::lock_guard<std::mutex> lock(mMutex);
95 
96     if (mTimeStats.statsStart == 0) {
97         return AStatsManager_PULL_SKIP;
98     }
99     flushPowerTimeLocked();
100 
101     AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data);
102     mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_GLOBAL_INFO);
103     mStatsDelegate->statsEventWriteInt64(event, mTimeStats.totalFrames);
104     mStatsDelegate->statsEventWriteInt64(event, mTimeStats.missedFrames);
105     mStatsDelegate->statsEventWriteInt64(event, mTimeStats.clientCompositionFrames);
106     mStatsDelegate->statsEventWriteInt64(event, mTimeStats.displayOnTime);
107     mStatsDelegate->statsEventWriteInt64(event, mTimeStats.presentToPresent.totalTime());
108     mStatsDelegate->statsEventWriteInt32(event, mTimeStats.displayEventConnectionsCount);
109     std::string frameDurationBytes =
110             histogramToProtoByteString(mTimeStats.frameDuration.hist, mMaxPulledHistogramBuckets);
111     mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)frameDurationBytes.c_str(),
112                                              frameDurationBytes.size());
113     std::string renderEngineTimingBytes =
114             histogramToProtoByteString(mTimeStats.renderEngineTiming.hist,
115                                        mMaxPulledHistogramBuckets);
116     mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)renderEngineTimingBytes.c_str(),
117                                              renderEngineTimingBytes.size());
118     mStatsDelegate->statsEventBuild(event);
119     clearGlobalLocked();
120 
121     return AStatsManager_PULL_SUCCESS;
122 }
123 
populateLayerAtom(AStatsEventList * data)124 AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventList* data) {
125     std::lock_guard<std::mutex> lock(mMutex);
126 
127     std::vector<TimeStatsHelper::TimeStatsLayer const*> dumpStats;
128     for (const auto& ele : mTimeStats.stats) {
129         dumpStats.push_back(&ele.second);
130     }
131 
132     std::sort(dumpStats.begin(), dumpStats.end(),
133               [](TimeStatsHelper::TimeStatsLayer const* l,
134                  TimeStatsHelper::TimeStatsLayer const* r) {
135                   return l->totalFrames > r->totalFrames;
136               });
137 
138     if (mMaxPulledLayers < dumpStats.size()) {
139         dumpStats.resize(mMaxPulledLayers);
140     }
141 
142     for (const auto& layer : dumpStats) {
143         AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data);
144         mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_LAYER_INFO);
145         mStatsDelegate->statsEventWriteString8(event, layer->layerName.c_str());
146         mStatsDelegate->statsEventWriteInt64(event, layer->totalFrames);
147         mStatsDelegate->statsEventWriteInt64(event, layer->droppedFrames);
148 
149         for (const auto& name : kHistogramNames) {
150             const auto& histogram = layer->deltas.find(name);
151             if (histogram == layer->deltas.cend()) {
152                 mStatsDelegate->statsEventWriteByteArray(event, nullptr, 0);
153             } else {
154                 std::string bytes = histogramToProtoByteString(histogram->second.hist,
155                                                                mMaxPulledHistogramBuckets);
156                 mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)bytes.c_str(),
157                                                          bytes.size());
158             }
159         }
160 
161         mStatsDelegate->statsEventWriteInt64(event, layer->lateAcquireFrames);
162         mStatsDelegate->statsEventWriteInt64(event, layer->badDesiredPresentFrames);
163 
164         mStatsDelegate->statsEventBuild(event);
165     }
166     clearLayersLocked();
167 
168     return AStatsManager_PULL_SUCCESS;
169 }
170 
TimeStats()171 TimeStats::TimeStats() : TimeStats(nullptr, std::nullopt, std::nullopt) {}
172 
TimeStats(std::unique_ptr<StatsEventDelegate> statsDelegate,std::optional<size_t> maxPulledLayers,std::optional<size_t> maxPulledHistogramBuckets)173 TimeStats::TimeStats(std::unique_ptr<StatsEventDelegate> statsDelegate,
174                      std::optional<size_t> maxPulledLayers,
175                      std::optional<size_t> maxPulledHistogramBuckets) {
176     if (statsDelegate != nullptr) {
177         mStatsDelegate = std::move(statsDelegate);
178     }
179 
180     if (maxPulledLayers) {
181         mMaxPulledLayers = *maxPulledLayers;
182     }
183 
184     if (maxPulledHistogramBuckets) {
185         mMaxPulledHistogramBuckets = *maxPulledHistogramBuckets;
186     }
187 }
188 
~TimeStats()189 TimeStats::~TimeStats() {
190     std::lock_guard<std::mutex> lock(mMutex);
191     mStatsDelegate->clearStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO);
192     mStatsDelegate->clearStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO);
193 }
194 
onBootFinished()195 void TimeStats::onBootFinished() {
196     std::lock_guard<std::mutex> lock(mMutex);
197     mStatsDelegate->setStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO,
198                                              nullptr, TimeStats::pullAtomCallback, this);
199     mStatsDelegate->setStatsPullAtomCallback(android::util::SURFACEFLINGER_STATS_LAYER_INFO,
200                                              nullptr, TimeStats::pullAtomCallback, this);
201 }
202 
parseArgs(bool asProto,const Vector<String16> & args,std::string & result)203 void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
204     ATRACE_CALL();
205 
206     std::unordered_map<std::string, int32_t> argsMap;
207     for (size_t index = 0; index < args.size(); ++index) {
208         argsMap[std::string(String8(args[index]).c_str())] = index;
209     }
210 
211     if (argsMap.count("-disable")) {
212         disable();
213     }
214 
215     if (argsMap.count("-dump")) {
216         std::optional<uint32_t> maxLayers = std::nullopt;
217         auto iter = argsMap.find("-maxlayers");
218         if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
219             int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
220             value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
221             maxLayers = static_cast<uint32_t>(value);
222         }
223 
224         dump(asProto, maxLayers, result);
225     }
226 
227     if (argsMap.count("-clear")) {
228         clearAll();
229     }
230 
231     if (argsMap.count("-enable")) {
232         enable();
233     }
234 }
235 
miniDump()236 std::string TimeStats::miniDump() {
237     ATRACE_CALL();
238 
239     std::string result = "TimeStats miniDump:\n";
240     std::lock_guard<std::mutex> lock(mMutex);
241     android::base::StringAppendF(&result, "Number of layers currently being tracked is %zu\n",
242                                  mTimeStatsTracker.size());
243     android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
244                                  mTimeStats.stats.size());
245     return result;
246 }
247 
incrementTotalFrames()248 void TimeStats::incrementTotalFrames() {
249     if (!mEnabled.load()) return;
250 
251     ATRACE_CALL();
252 
253     std::lock_guard<std::mutex> lock(mMutex);
254     mTimeStats.totalFrames++;
255 }
256 
incrementMissedFrames()257 void TimeStats::incrementMissedFrames() {
258     if (!mEnabled.load()) return;
259 
260     ATRACE_CALL();
261 
262     std::lock_guard<std::mutex> lock(mMutex);
263     mTimeStats.missedFrames++;
264 }
265 
incrementClientCompositionFrames()266 void TimeStats::incrementClientCompositionFrames() {
267     if (!mEnabled.load()) return;
268 
269     ATRACE_CALL();
270 
271     std::lock_guard<std::mutex> lock(mMutex);
272     mTimeStats.clientCompositionFrames++;
273 }
274 
incrementClientCompositionReusedFrames()275 void TimeStats::incrementClientCompositionReusedFrames() {
276     if (!mEnabled.load()) return;
277 
278     ATRACE_CALL();
279 
280     std::lock_guard<std::mutex> lock(mMutex);
281     mTimeStats.clientCompositionReusedFrames++;
282 }
283 
incrementRefreshRateSwitches()284 void TimeStats::incrementRefreshRateSwitches() {
285     if (!mEnabled.load()) return;
286 
287     ATRACE_CALL();
288 
289     std::lock_guard<std::mutex> lock(mMutex);
290     mTimeStats.refreshRateSwitches++;
291 }
292 
incrementCompositionStrategyChanges()293 void TimeStats::incrementCompositionStrategyChanges() {
294     if (!mEnabled.load()) return;
295 
296     ATRACE_CALL();
297 
298     std::lock_guard<std::mutex> lock(mMutex);
299     mTimeStats.compositionStrategyChanges++;
300 }
301 
recordDisplayEventConnectionCount(int32_t count)302 void TimeStats::recordDisplayEventConnectionCount(int32_t count) {
303     if (!mEnabled.load()) return;
304 
305     ATRACE_CALL();
306 
307     std::lock_guard<std::mutex> lock(mMutex);
308     mTimeStats.displayEventConnectionsCount =
309             std::max(mTimeStats.displayEventConnectionsCount, count);
310 }
311 
msBetween(nsecs_t start,nsecs_t end)312 static int32_t msBetween(nsecs_t start, nsecs_t end) {
313     int64_t delta = std::chrono::duration_cast<std::chrono::milliseconds>(
314                             std::chrono::nanoseconds(end - start))
315                             .count();
316     delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
317     return static_cast<int32_t>(delta);
318 }
319 
recordFrameDuration(nsecs_t startTime,nsecs_t endTime)320 void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
321     if (!mEnabled.load()) return;
322 
323     std::lock_guard<std::mutex> lock(mMutex);
324     if (mPowerTime.powerMode == PowerMode::ON) {
325         mTimeStats.frameDuration.insert(msBetween(startTime, endTime));
326     }
327 }
328 
recordRenderEngineDuration(nsecs_t startTime,nsecs_t endTime)329 void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) {
330     if (!mEnabled.load()) return;
331 
332     std::lock_guard<std::mutex> lock(mMutex);
333     if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
334         ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
335         mGlobalRecord.renderEngineDurations.pop_front();
336     }
337     mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
338 }
339 
recordRenderEngineDuration(nsecs_t startTime,const std::shared_ptr<FenceTime> & endTime)340 void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
341                                            const std::shared_ptr<FenceTime>& endTime) {
342     if (!mEnabled.load()) return;
343 
344     std::lock_guard<std::mutex> lock(mMutex);
345     if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
346         ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
347         mGlobalRecord.renderEngineDurations.pop_front();
348     }
349     mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
350 }
351 
recordReadyLocked(int32_t layerId,TimeRecord * timeRecord)352 bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
353     if (!timeRecord->ready) {
354         ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
355               timeRecord->frameTime.frameNumber);
356         return false;
357     }
358 
359     if (timeRecord->acquireFence != nullptr) {
360         if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
361             return false;
362         }
363         if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
364             timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
365             timeRecord->acquireFence = nullptr;
366         } else {
367             ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerId,
368                   timeRecord->frameTime.frameNumber);
369         }
370     }
371 
372     if (timeRecord->presentFence != nullptr) {
373         if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
374             return false;
375         }
376         if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
377             timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
378             timeRecord->presentFence = nullptr;
379         } else {
380             ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerId,
381                   timeRecord->frameTime.frameNumber);
382         }
383     }
384 
385     return true;
386 }
387 
flushAvailableRecordsToStatsLocked(int32_t layerId)388 void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
389     ATRACE_CALL();
390 
391     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
392     TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
393     std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
394     while (!timeRecords.empty()) {
395         if (!recordReadyLocked(layerId, &timeRecords[0])) break;
396         ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId,
397               timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
398 
399         if (prevTimeRecord.ready) {
400             const std::string& layerName = layerRecord.layerName;
401             if (!mTimeStats.stats.count(layerName)) {
402                 mTimeStats.stats[layerName].layerName = layerName;
403             }
404             TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
405             timeStatsLayer.totalFrames++;
406             timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
407             timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames;
408             timeStatsLayer.badDesiredPresentFrames += layerRecord.badDesiredPresentFrames;
409 
410             layerRecord.droppedFrames = 0;
411             layerRecord.lateAcquireFrames = 0;
412             layerRecord.badDesiredPresentFrames = 0;
413 
414             const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
415                                                       timeRecords[0].frameTime.acquireTime);
416             ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerId,
417                   timeRecords[0].frameTime.frameNumber, postToAcquireMs);
418             timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
419 
420             const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
421                                                       timeRecords[0].frameTime.presentTime);
422             ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerId,
423                   timeRecords[0].frameTime.frameNumber, postToPresentMs);
424             timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
425 
426             const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
427                                                          timeRecords[0].frameTime.presentTime);
428             ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerId,
429                   timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
430             timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
431 
432             const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
433                                                        timeRecords[0].frameTime.presentTime);
434             ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerId,
435                   timeRecords[0].frameTime.frameNumber, latchToPresentMs);
436             timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
437 
438             const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
439                                                          timeRecords[0].frameTime.presentTime);
440             ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerId,
441                   timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
442             timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
443 
444             const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
445                                                          timeRecords[0].frameTime.presentTime);
446             ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerId,
447                   timeRecords[0].frameTime.frameNumber, presentToPresentMs);
448             timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
449         }
450         prevTimeRecord = timeRecords[0];
451         timeRecords.pop_front();
452         layerRecord.waitData--;
453     }
454 }
455 
456 static constexpr const char* kPopupWindowPrefix = "PopupWindow";
457 static const size_t kMinLenLayerName = std::strlen(kPopupWindowPrefix);
458 
459 // Avoid tracking the "PopupWindow:<random hash>#<number>" layers
layerNameIsValid(const std::string & layerName)460 static bool layerNameIsValid(const std::string& layerName) {
461     return layerName.length() >= kMinLenLayerName &&
462             layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0;
463 }
464 
setPostTime(int32_t layerId,uint64_t frameNumber,const std::string & layerName,nsecs_t postTime)465 void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
466                             nsecs_t postTime) {
467     if (!mEnabled.load()) return;
468 
469     ATRACE_CALL();
470     ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(),
471           postTime);
472 
473     std::lock_guard<std::mutex> lock(mMutex);
474     if (!mTimeStats.stats.count(layerName) && mTimeStats.stats.size() >= MAX_NUM_LAYER_STATS) {
475         return;
476     }
477     if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
478         layerNameIsValid(layerName)) {
479         mTimeStatsTracker[layerId].layerName = layerName;
480     }
481     if (!mTimeStatsTracker.count(layerId)) return;
482     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
483     if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
484         ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
485               layerId, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
486         mTimeStatsTracker.erase(layerId);
487         return;
488     }
489     // For most media content, the acquireFence is invalid because the buffer is
490     // ready at the queueBuffer stage. In this case, acquireTime should be given
491     // a default value as postTime.
492     TimeRecord timeRecord = {
493             .frameTime =
494                     {
495                             .frameNumber = frameNumber,
496                             .postTime = postTime,
497                             .latchTime = postTime,
498                             .acquireTime = postTime,
499                             .desiredTime = postTime,
500                     },
501     };
502     layerRecord.timeRecords.push_back(timeRecord);
503     if (layerRecord.waitData < 0 ||
504         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
505         layerRecord.waitData = layerRecord.timeRecords.size() - 1;
506 }
507 
setLatchTime(int32_t layerId,uint64_t frameNumber,nsecs_t latchTime)508 void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) {
509     if (!mEnabled.load()) return;
510 
511     ATRACE_CALL();
512     ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime);
513 
514     std::lock_guard<std::mutex> lock(mMutex);
515     if (!mTimeStatsTracker.count(layerId)) return;
516     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
517     if (layerRecord.waitData < 0 ||
518         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
519         return;
520     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
521     if (timeRecord.frameTime.frameNumber == frameNumber) {
522         timeRecord.frameTime.latchTime = latchTime;
523     }
524 }
525 
incrementLatchSkipped(int32_t layerId,LatchSkipReason reason)526 void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) {
527     if (!mEnabled.load()) return;
528 
529     ATRACE_CALL();
530     ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId,
531           static_cast<std::underlying_type<LatchSkipReason>::type>(reason));
532 
533     std::lock_guard<std::mutex> lock(mMutex);
534     if (!mTimeStatsTracker.count(layerId)) return;
535     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
536 
537     switch (reason) {
538         case LatchSkipReason::LateAcquire:
539             layerRecord.lateAcquireFrames++;
540             break;
541     }
542 }
543 
incrementBadDesiredPresent(int32_t layerId)544 void TimeStats::incrementBadDesiredPresent(int32_t layerId) {
545     if (!mEnabled.load()) return;
546 
547     ATRACE_CALL();
548     ALOGV("[%d]-BadDesiredPresent", layerId);
549 
550     std::lock_guard<std::mutex> lock(mMutex);
551     if (!mTimeStatsTracker.count(layerId)) return;
552     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
553     layerRecord.badDesiredPresentFrames++;
554 }
555 
setDesiredTime(int32_t layerId,uint64_t frameNumber,nsecs_t desiredTime)556 void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
557     if (!mEnabled.load()) return;
558 
559     ATRACE_CALL();
560     ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime);
561 
562     std::lock_guard<std::mutex> lock(mMutex);
563     if (!mTimeStatsTracker.count(layerId)) return;
564     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
565     if (layerRecord.waitData < 0 ||
566         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
567         return;
568     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
569     if (timeRecord.frameTime.frameNumber == frameNumber) {
570         timeRecord.frameTime.desiredTime = desiredTime;
571     }
572 }
573 
setAcquireTime(int32_t layerId,uint64_t frameNumber,nsecs_t acquireTime)574 void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) {
575     if (!mEnabled.load()) return;
576 
577     ATRACE_CALL();
578     ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime);
579 
580     std::lock_guard<std::mutex> lock(mMutex);
581     if (!mTimeStatsTracker.count(layerId)) return;
582     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
583     if (layerRecord.waitData < 0 ||
584         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
585         return;
586     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
587     if (timeRecord.frameTime.frameNumber == frameNumber) {
588         timeRecord.frameTime.acquireTime = acquireTime;
589     }
590 }
591 
setAcquireFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & acquireFence)592 void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber,
593                                 const std::shared_ptr<FenceTime>& acquireFence) {
594     if (!mEnabled.load()) return;
595 
596     ATRACE_CALL();
597     ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber,
598           acquireFence->getSignalTime());
599 
600     std::lock_guard<std::mutex> lock(mMutex);
601     if (!mTimeStatsTracker.count(layerId)) return;
602     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
603     if (layerRecord.waitData < 0 ||
604         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
605         return;
606     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
607     if (timeRecord.frameTime.frameNumber == frameNumber) {
608         timeRecord.acquireFence = acquireFence;
609     }
610 }
611 
setPresentTime(int32_t layerId,uint64_t frameNumber,nsecs_t presentTime)612 void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) {
613     if (!mEnabled.load()) return;
614 
615     ATRACE_CALL();
616     ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime);
617 
618     std::lock_guard<std::mutex> lock(mMutex);
619     if (!mTimeStatsTracker.count(layerId)) return;
620     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
621     if (layerRecord.waitData < 0 ||
622         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
623         return;
624     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
625     if (timeRecord.frameTime.frameNumber == frameNumber) {
626         timeRecord.frameTime.presentTime = presentTime;
627         timeRecord.ready = true;
628         layerRecord.waitData++;
629     }
630 
631     flushAvailableRecordsToStatsLocked(layerId);
632 }
633 
setPresentFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & presentFence)634 void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber,
635                                 const std::shared_ptr<FenceTime>& presentFence) {
636     if (!mEnabled.load()) return;
637 
638     ATRACE_CALL();
639     ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber,
640           presentFence->getSignalTime());
641 
642     std::lock_guard<std::mutex> lock(mMutex);
643     if (!mTimeStatsTracker.count(layerId)) return;
644     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
645     if (layerRecord.waitData < 0 ||
646         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
647         return;
648     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
649     if (timeRecord.frameTime.frameNumber == frameNumber) {
650         timeRecord.presentFence = presentFence;
651         timeRecord.ready = true;
652         layerRecord.waitData++;
653     }
654 
655     flushAvailableRecordsToStatsLocked(layerId);
656 }
657 
onDestroy(int32_t layerId)658 void TimeStats::onDestroy(int32_t layerId) {
659     ATRACE_CALL();
660     ALOGV("[%d]-onDestroy", layerId);
661     std::lock_guard<std::mutex> lock(mMutex);
662     mTimeStatsTracker.erase(layerId);
663 }
664 
removeTimeRecord(int32_t layerId,uint64_t frameNumber)665 void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) {
666     if (!mEnabled.load()) return;
667 
668     ATRACE_CALL();
669     ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber);
670 
671     std::lock_guard<std::mutex> lock(mMutex);
672     if (!mTimeStatsTracker.count(layerId)) return;
673     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
674     size_t removeAt = 0;
675     for (const TimeRecord& record : layerRecord.timeRecords) {
676         if (record.frameTime.frameNumber == frameNumber) break;
677         removeAt++;
678     }
679     if (removeAt == layerRecord.timeRecords.size()) return;
680     layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
681     if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
682         layerRecord.waitData--;
683     }
684     layerRecord.droppedFrames++;
685 }
686 
flushPowerTimeLocked()687 void TimeStats::flushPowerTimeLocked() {
688     if (!mEnabled.load()) return;
689 
690     nsecs_t curTime = systemTime();
691     // elapsedTime is in milliseconds.
692     int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
693 
694     switch (mPowerTime.powerMode) {
695         case PowerMode::ON:
696             mTimeStats.displayOnTime += elapsedTime;
697             break;
698         case PowerMode::OFF:
699         case PowerMode::DOZE:
700         case PowerMode::DOZE_SUSPEND:
701         case PowerMode::ON_SUSPEND:
702         default:
703             break;
704     }
705 
706     mPowerTime.prevTime = curTime;
707 }
708 
setPowerMode(PowerMode powerMode)709 void TimeStats::setPowerMode(PowerMode powerMode) {
710     if (!mEnabled.load()) {
711         std::lock_guard<std::mutex> lock(mMutex);
712         mPowerTime.powerMode = powerMode;
713         return;
714     }
715 
716     std::lock_guard<std::mutex> lock(mMutex);
717     if (powerMode == mPowerTime.powerMode) return;
718 
719     flushPowerTimeLocked();
720     mPowerTime.powerMode = powerMode;
721 }
722 
recordRefreshRate(uint32_t fps,nsecs_t duration)723 void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
724     std::lock_guard<std::mutex> lock(mMutex);
725     if (mTimeStats.refreshRateStats.count(fps)) {
726         mTimeStats.refreshRateStats[fps] += duration;
727     } else {
728         mTimeStats.refreshRateStats.insert({fps, duration});
729     }
730 }
731 
flushAvailableGlobalRecordsToStatsLocked()732 void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
733     ATRACE_CALL();
734 
735     while (!mGlobalRecord.presentFences.empty()) {
736         const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
737         if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
738 
739         if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
740             ALOGE("GlobalPresentFence is invalid!");
741             mGlobalRecord.prevPresentTime = 0;
742             mGlobalRecord.presentFences.pop_front();
743             continue;
744         }
745 
746         ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
747               mGlobalRecord.presentFences.front()->getSignalTime());
748 
749         if (mGlobalRecord.prevPresentTime != 0) {
750             const int32_t presentToPresentMs =
751                     msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
752             ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
753                   presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
754             mTimeStats.presentToPresent.insert(presentToPresentMs);
755         }
756 
757         mGlobalRecord.prevPresentTime = curPresentTime;
758         mGlobalRecord.presentFences.pop_front();
759     }
760     while (!mGlobalRecord.renderEngineDurations.empty()) {
761         const auto duration = mGlobalRecord.renderEngineDurations.front();
762         const auto& endTime = duration.endTime;
763 
764         nsecs_t endNs = -1;
765 
766         if (auto val = std::get_if<nsecs_t>(&endTime)) {
767             endNs = *val;
768         } else {
769             endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
770         }
771 
772         if (endNs == Fence::SIGNAL_TIME_PENDING) break;
773 
774         if (endNs < 0) {
775             ALOGE("RenderEngineTiming is invalid!");
776             mGlobalRecord.renderEngineDurations.pop_front();
777             continue;
778         }
779 
780         const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
781         mTimeStats.renderEngineTiming.insert(renderEngineMs);
782 
783         mGlobalRecord.renderEngineDurations.pop_front();
784     }
785 }
786 
setPresentFenceGlobal(const std::shared_ptr<FenceTime> & presentFence)787 void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
788     if (!mEnabled.load()) return;
789 
790     ATRACE_CALL();
791     std::lock_guard<std::mutex> lock(mMutex);
792     if (presentFence == nullptr || !presentFence->isValid()) {
793         mGlobalRecord.prevPresentTime = 0;
794         return;
795     }
796 
797     if (mPowerTime.powerMode != PowerMode::ON) {
798         // Try flushing the last present fence on PowerMode::ON.
799         flushAvailableGlobalRecordsToStatsLocked();
800         mGlobalRecord.presentFences.clear();
801         mGlobalRecord.prevPresentTime = 0;
802         return;
803     }
804 
805     if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
806         // The front presentFence must be trapped in pending status in this
807         // case. Try dequeuing the front one to recover.
808         ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
809         mGlobalRecord.prevPresentTime = 0;
810         mGlobalRecord.presentFences.pop_front();
811     }
812 
813     mGlobalRecord.presentFences.emplace_back(presentFence);
814     flushAvailableGlobalRecordsToStatsLocked();
815 }
816 
enable()817 void TimeStats::enable() {
818     if (mEnabled.load()) return;
819 
820     ATRACE_CALL();
821 
822     std::lock_guard<std::mutex> lock(mMutex);
823     mEnabled.store(true);
824     mTimeStats.statsStart = static_cast<int64_t>(std::time(0));
825     mPowerTime.prevTime = systemTime();
826     ALOGD("Enabled");
827 }
828 
disable()829 void TimeStats::disable() {
830     if (!mEnabled.load()) return;
831 
832     ATRACE_CALL();
833 
834     std::lock_guard<std::mutex> lock(mMutex);
835     flushPowerTimeLocked();
836     mEnabled.store(false);
837     mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
838     ALOGD("Disabled");
839 }
840 
clearAll()841 void TimeStats::clearAll() {
842     std::lock_guard<std::mutex> lock(mMutex);
843     clearGlobalLocked();
844     clearLayersLocked();
845 }
846 
clearGlobalLocked()847 void TimeStats::clearGlobalLocked() {
848     ATRACE_CALL();
849 
850     mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
851     mTimeStats.statsEnd = 0;
852     mTimeStats.totalFrames = 0;
853     mTimeStats.missedFrames = 0;
854     mTimeStats.clientCompositionFrames = 0;
855     mTimeStats.clientCompositionReusedFrames = 0;
856     mTimeStats.refreshRateSwitches = 0;
857     mTimeStats.compositionStrategyChanges = 0;
858     mTimeStats.displayEventConnectionsCount = 0;
859     mTimeStats.displayOnTime = 0;
860     mTimeStats.presentToPresent.hist.clear();
861     mTimeStats.frameDuration.hist.clear();
862     mTimeStats.renderEngineTiming.hist.clear();
863     mTimeStats.refreshRateStats.clear();
864     mPowerTime.prevTime = systemTime();
865     mGlobalRecord.prevPresentTime = 0;
866     mGlobalRecord.presentFences.clear();
867     ALOGD("Cleared global stats");
868 }
869 
clearLayersLocked()870 void TimeStats::clearLayersLocked() {
871     ATRACE_CALL();
872 
873     mTimeStatsTracker.clear();
874     mTimeStats.stats.clear();
875     ALOGD("Cleared layer stats");
876 }
877 
isEnabled()878 bool TimeStats::isEnabled() {
879     return mEnabled.load();
880 }
881 
dump(bool asProto,std::optional<uint32_t> maxLayers,std::string & result)882 void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
883     ATRACE_CALL();
884 
885     std::lock_guard<std::mutex> lock(mMutex);
886     if (mTimeStats.statsStart == 0) {
887         return;
888     }
889 
890     mTimeStats.statsEnd = static_cast<int64_t>(std::time(0));
891 
892     flushPowerTimeLocked();
893 
894     if (asProto) {
895         ALOGD("Dumping TimeStats as proto");
896         SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
897         result.append(timeStatsProto.SerializeAsString());
898     } else {
899         ALOGD("Dumping TimeStats as text");
900         result.append(mTimeStats.toString(maxLayers));
901         result.append("\n");
902     }
903 }
904 
905 } // namespace impl
906 
907 } // namespace android
908 
909 // TODO(b/129481165): remove the #pragma below and fix conversion issues
910 #pragma clang diagnostic pop // ignored "-Wconversion"
911