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 #undef LOG_TAG
18 #define LOG_TAG "TimeStats"
19 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
20 
21 #include <android-base/stringprintf.h>
22 #include <log/log.h>
23 #include <timestatsatomsproto/TimeStatsAtomsProtoHeader.h>
24 #include <utils/String8.h>
25 #include <utils/Timers.h>
26 #include <utils/Trace.h>
27 
28 #include <algorithm>
29 #include <chrono>
30 #include <cmath>
31 #include <unordered_map>
32 
33 #include "TimeStats.h"
34 #include "timestatsproto/TimeStatsHelper.h"
35 
36 namespace android {
37 
38 namespace impl {
39 
40 namespace {
41 
histogramToProto(const std::unordered_map<int32_t,int32_t> & histogram,size_t maxPulledHistogramBuckets)42 FrameTimingHistogram histogramToProto(const std::unordered_map<int32_t, int32_t>& histogram,
43                                       size_t maxPulledHistogramBuckets) {
44     auto buckets = std::vector<std::pair<int32_t, int32_t>>(histogram.begin(), histogram.end());
45     std::sort(buckets.begin(), buckets.end(),
46               [](std::pair<int32_t, int32_t>& left, std::pair<int32_t, int32_t>& right) {
47                   return left.second > right.second;
48               });
49 
50     FrameTimingHistogram histogramProto;
51     int histogramSize = 0;
52     for (const auto& bucket : buckets) {
53         if (++histogramSize > maxPulledHistogramBuckets) {
54             break;
55         }
56         histogramProto.add_time_millis_buckets((int32_t)bucket.first);
57         histogramProto.add_frame_counts((int64_t)bucket.second);
58     }
59     return histogramProto;
60 }
61 
gameModeToProto(GameMode gameMode)62 SurfaceflingerStatsLayerInfo_GameMode gameModeToProto(GameMode gameMode) {
63     switch (gameMode) {
64         case GameMode::Unsupported:
65             return SurfaceflingerStatsLayerInfo::GAME_MODE_UNSUPPORTED;
66         case GameMode::Standard:
67             return SurfaceflingerStatsLayerInfo::GAME_MODE_STANDARD;
68         case GameMode::Performance:
69             return SurfaceflingerStatsLayerInfo::GAME_MODE_PERFORMANCE;
70         case GameMode::Battery:
71             return SurfaceflingerStatsLayerInfo::GAME_MODE_BATTERY;
72         case GameMode::Custom:
73             return SurfaceflingerStatsLayerInfo::GAME_MODE_CUSTOM;
74         default:
75             return SurfaceflingerStatsLayerInfo::GAME_MODE_UNSPECIFIED;
76     }
77 }
78 
frameRateVoteToProto(const TimeStats::SetFrameRateVote & setFrameRateVote)79 SurfaceflingerStatsLayerInfo_SetFrameRateVote frameRateVoteToProto(
80         const TimeStats::SetFrameRateVote& setFrameRateVote) {
81     using FrameRateCompatibilityEnum =
82             SurfaceflingerStatsLayerInfo::SetFrameRateVote::FrameRateCompatibility;
83     using SeamlessnessEnum = SurfaceflingerStatsLayerInfo::SetFrameRateVote::Seamlessness;
84 
85     SurfaceflingerStatsLayerInfo_SetFrameRateVote proto;
86     proto.set_frame_rate(setFrameRateVote.frameRate);
87     proto.set_frame_rate_compatibility(
88             static_cast<FrameRateCompatibilityEnum>(setFrameRateVote.frameRateCompatibility));
89     proto.set_seamlessness(static_cast<SeamlessnessEnum>(setFrameRateVote.seamlessness));
90     return proto;
91 }
92 } // namespace
93 
populateGlobalAtom(std::vector<uint8_t> * pulledData)94 bool TimeStats::populateGlobalAtom(std::vector<uint8_t>* pulledData) {
95     std::lock_guard<std::mutex> lock(mMutex);
96 
97     if (mTimeStats.statsStartLegacy == 0) {
98         return false;
99     }
100     flushPowerTimeLocked();
101     SurfaceflingerStatsGlobalInfoWrapper atomList;
102     for (const auto& globalSlice : mTimeStats.stats) {
103         SurfaceflingerStatsGlobalInfo* atom = atomList.add_atom();
104         atom->set_total_frames(mTimeStats.totalFramesLegacy);
105         atom->set_missed_frames(mTimeStats.missedFramesLegacy);
106         atom->set_client_composition_frames(mTimeStats.clientCompositionFramesLegacy);
107         atom->set_display_on_millis(mTimeStats.displayOnTimeLegacy);
108         atom->set_animation_millis(mTimeStats.presentToPresentLegacy.totalTime());
109         // Deprecated
110         atom->set_event_connection_count(0);
111         *atom->mutable_frame_duration() =
112                 histogramToProto(mTimeStats.frameDurationLegacy.hist, mMaxPulledHistogramBuckets);
113         *atom->mutable_render_engine_timing() =
114                 histogramToProto(mTimeStats.renderEngineTimingLegacy.hist,
115                                  mMaxPulledHistogramBuckets);
116         atom->set_total_timeline_frames(globalSlice.second.jankPayload.totalFrames);
117         atom->set_total_janky_frames(globalSlice.second.jankPayload.totalJankyFrames);
118         atom->set_total_janky_frames_with_long_cpu(globalSlice.second.jankPayload.totalSFLongCpu);
119         atom->set_total_janky_frames_with_long_gpu(globalSlice.second.jankPayload.totalSFLongGpu);
120         atom->set_total_janky_frames_sf_unattributed(
121                 globalSlice.second.jankPayload.totalSFUnattributed);
122         atom->set_total_janky_frames_app_unattributed(
123                 globalSlice.second.jankPayload.totalAppUnattributed);
124         atom->set_total_janky_frames_sf_scheduling(
125                 globalSlice.second.jankPayload.totalSFScheduling);
126         atom->set_total_jank_frames_sf_prediction_error(
127                 globalSlice.second.jankPayload.totalSFPredictionError);
128         atom->set_total_jank_frames_app_buffer_stuffing(
129                 globalSlice.second.jankPayload.totalAppBufferStuffing);
130         atom->set_display_refresh_rate_bucket(globalSlice.first.displayRefreshRateBucket);
131         *atom->mutable_sf_deadline_misses() =
132                 histogramToProto(globalSlice.second.displayDeadlineDeltas.hist,
133                                  mMaxPulledHistogramBuckets);
134         *atom->mutable_sf_prediction_errors() =
135                 histogramToProto(globalSlice.second.displayPresentDeltas.hist,
136                                  mMaxPulledHistogramBuckets);
137         atom->set_render_rate_bucket(globalSlice.first.renderRateBucket);
138     }
139 
140     // Always clear data.
141     clearGlobalLocked();
142 
143     pulledData->resize(atomList.ByteSizeLong());
144     return atomList.SerializeToArray(pulledData->data(), atomList.ByteSizeLong());
145 }
146 
populateLayerAtom(std::vector<uint8_t> * pulledData)147 bool TimeStats::populateLayerAtom(std::vector<uint8_t>* pulledData) {
148     std::lock_guard<std::mutex> lock(mMutex);
149 
150     std::vector<TimeStatsHelper::TimeStatsLayer*> dumpStats;
151     uint32_t numLayers = 0;
152     for (const auto& globalSlice : mTimeStats.stats) {
153         numLayers += globalSlice.second.stats.size();
154     }
155 
156     dumpStats.reserve(numLayers);
157 
158     for (auto& globalSlice : mTimeStats.stats) {
159         for (auto& layerSlice : globalSlice.second.stats) {
160             dumpStats.push_back(&layerSlice.second);
161         }
162     }
163 
164     std::sort(dumpStats.begin(), dumpStats.end(),
165               [](TimeStatsHelper::TimeStatsLayer const* l,
166                  TimeStatsHelper::TimeStatsLayer const* r) {
167                   return l->totalFrames > r->totalFrames;
168               });
169 
170     if (mMaxPulledLayers < dumpStats.size()) {
171         dumpStats.resize(mMaxPulledLayers);
172     }
173 
174     SurfaceflingerStatsLayerInfoWrapper atomList;
175     for (auto& layer : dumpStats) {
176         SurfaceflingerStatsLayerInfo* atom = atomList.add_atom();
177         atom->set_layer_name(layer->layerName);
178         atom->set_total_frames(layer->totalFrames);
179         atom->set_dropped_frames(layer->droppedFrames);
180         const auto& present2PresentHist = layer->deltas.find("present2present");
181         if (present2PresentHist != layer->deltas.cend()) {
182             *atom->mutable_present_to_present() =
183                     histogramToProto(present2PresentHist->second.hist, mMaxPulledHistogramBuckets);
184         }
185         const auto& present2PresentDeltaHist = layer->deltas.find("present2presentDelta");
186         if (present2PresentDeltaHist != layer->deltas.cend()) {
187             *atom->mutable_present_to_present_delta() =
188                     histogramToProto(present2PresentDeltaHist->second.hist,
189                                      mMaxPulledHistogramBuckets);
190         }
191         const auto& post2presentHist = layer->deltas.find("post2present");
192         if (post2presentHist != layer->deltas.cend()) {
193             *atom->mutable_post_to_present() =
194                     histogramToProto(post2presentHist->second.hist, mMaxPulledHistogramBuckets);
195         }
196         const auto& acquire2presentHist = layer->deltas.find("acquire2present");
197         if (acquire2presentHist != layer->deltas.cend()) {
198             *atom->mutable_acquire_to_present() =
199                     histogramToProto(acquire2presentHist->second.hist, mMaxPulledHistogramBuckets);
200         }
201         const auto& latch2presentHist = layer->deltas.find("latch2present");
202         if (latch2presentHist != layer->deltas.cend()) {
203             *atom->mutable_latch_to_present() =
204                     histogramToProto(latch2presentHist->second.hist, mMaxPulledHistogramBuckets);
205         }
206         const auto& desired2presentHist = layer->deltas.find("desired2present");
207         if (desired2presentHist != layer->deltas.cend()) {
208             *atom->mutable_desired_to_present() =
209                     histogramToProto(desired2presentHist->second.hist, mMaxPulledHistogramBuckets);
210         }
211         const auto& post2acquireHist = layer->deltas.find("post2acquire");
212         if (post2acquireHist != layer->deltas.cend()) {
213             *atom->mutable_post_to_acquire() =
214                     histogramToProto(post2acquireHist->second.hist, mMaxPulledHistogramBuckets);
215         }
216 
217         atom->set_late_acquire_frames(layer->lateAcquireFrames);
218         atom->set_bad_desired_present_frames(layer->badDesiredPresentFrames);
219         atom->set_uid(layer->uid);
220         atom->set_total_timeline_frames(layer->jankPayload.totalFrames);
221         atom->set_total_janky_frames(layer->jankPayload.totalJankyFrames);
222         atom->set_total_janky_frames_with_long_cpu(layer->jankPayload.totalSFLongCpu);
223         atom->set_total_janky_frames_with_long_gpu(layer->jankPayload.totalSFLongGpu);
224         atom->set_total_janky_frames_sf_unattributed(layer->jankPayload.totalSFUnattributed);
225         atom->set_total_janky_frames_app_unattributed(layer->jankPayload.totalAppUnattributed);
226         atom->set_total_janky_frames_sf_scheduling(layer->jankPayload.totalSFScheduling);
227         atom->set_total_jank_frames_sf_prediction_error(layer->jankPayload.totalSFPredictionError);
228         atom->set_total_jank_frames_app_buffer_stuffing(layer->jankPayload.totalAppBufferStuffing);
229         atom->set_display_refresh_rate_bucket(layer->displayRefreshRateBucket);
230         atom->set_render_rate_bucket(layer->renderRateBucket);
231         *atom->mutable_set_frame_rate_vote() = frameRateVoteToProto(layer->setFrameRateVote);
232         *atom->mutable_app_deadline_misses() =
233                 histogramToProto(layer->deltas["appDeadlineDeltas"].hist,
234                                  mMaxPulledHistogramBuckets);
235         atom->set_game_mode(gameModeToProto(layer->gameMode));
236     }
237 
238     // Always clear data.
239     clearLayersLocked();
240 
241     pulledData->resize(atomList.ByteSizeLong());
242     return atomList.SerializeToArray(pulledData->data(), atomList.ByteSizeLong());
243 }
244 
TimeStats()245 TimeStats::TimeStats() : TimeStats(std::nullopt, std::nullopt) {}
246 
TimeStats(std::optional<size_t> maxPulledLayers,std::optional<size_t> maxPulledHistogramBuckets)247 TimeStats::TimeStats(std::optional<size_t> maxPulledLayers,
248                      std::optional<size_t> maxPulledHistogramBuckets) {
249     if (maxPulledLayers) {
250         mMaxPulledLayers = *maxPulledLayers;
251     }
252 
253     if (maxPulledHistogramBuckets) {
254         mMaxPulledHistogramBuckets = *maxPulledHistogramBuckets;
255     }
256 }
257 
onPullAtom(const int atomId,std::vector<uint8_t> * pulledData)258 bool TimeStats::onPullAtom(const int atomId, std::vector<uint8_t>* pulledData) {
259     bool success = false;
260     if (atomId == 10062) { // SURFACEFLINGER_STATS_GLOBAL_INFO
261         success = populateGlobalAtom(pulledData);
262     } else if (atomId == 10063) { // SURFACEFLINGER_STATS_LAYER_INFO
263         success = populateLayerAtom(pulledData);
264     }
265 
266     // Enable timestats now. The first full pull for a given build is expected to
267     // have empty or very little stats, as stats are first enabled after the
268     // first pull is completed for either the global or layer stats.
269     enable();
270     return success;
271 }
272 
parseArgs(bool asProto,const Vector<String16> & args,std::string & result)273 void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, std::string& result) {
274     ATRACE_CALL();
275 
276     std::unordered_map<std::string, int32_t> argsMap;
277     for (size_t index = 0; index < args.size(); ++index) {
278         argsMap[std::string(String8(args[index]).c_str())] = index;
279     }
280 
281     if (argsMap.count("-disable")) {
282         disable();
283     }
284 
285     if (argsMap.count("-dump")) {
286         std::optional<uint32_t> maxLayers = std::nullopt;
287         auto iter = argsMap.find("-maxlayers");
288         if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
289             int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
290             value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
291             maxLayers = static_cast<uint32_t>(value);
292         }
293 
294         dump(asProto, maxLayers, result);
295     }
296 
297     if (argsMap.count("-clear")) {
298         clearAll();
299     }
300 
301     if (argsMap.count("-enable")) {
302         enable();
303     }
304 }
305 
miniDump()306 std::string TimeStats::miniDump() {
307     ATRACE_CALL();
308 
309     std::string result = "TimeStats miniDump:\n";
310     std::lock_guard<std::mutex> lock(mMutex);
311     android::base::StringAppendF(&result, "Number of layers currently being tracked is %zu\n",
312                                  mTimeStatsTracker.size());
313     android::base::StringAppendF(&result, "Number of layers in the stats pool is %zu\n",
314                                  mTimeStats.stats.size());
315     return result;
316 }
317 
incrementTotalFrames()318 void TimeStats::incrementTotalFrames() {
319     if (!mEnabled.load()) return;
320 
321     ATRACE_CALL();
322 
323     std::lock_guard<std::mutex> lock(mMutex);
324     mTimeStats.totalFramesLegacy++;
325 }
326 
incrementMissedFrames()327 void TimeStats::incrementMissedFrames() {
328     if (!mEnabled.load()) return;
329 
330     ATRACE_CALL();
331 
332     std::lock_guard<std::mutex> lock(mMutex);
333     mTimeStats.missedFramesLegacy++;
334 }
335 
pushCompositionStrategyState(const TimeStats::ClientCompositionRecord & record)336 void TimeStats::pushCompositionStrategyState(const TimeStats::ClientCompositionRecord& record) {
337     if (!mEnabled.load() || !record.hasInterestingData()) {
338         return;
339     }
340 
341     ATRACE_CALL();
342 
343     std::lock_guard<std::mutex> lock(mMutex);
344     if (record.changed) mTimeStats.compositionStrategyChangesLegacy++;
345     if (record.hadClientComposition) mTimeStats.clientCompositionFramesLegacy++;
346     if (record.reused) mTimeStats.clientCompositionReusedFramesLegacy++;
347     if (record.predicted) mTimeStats.compositionStrategyPredictedLegacy++;
348     if (record.predictionSucceeded) mTimeStats.compositionStrategyPredictionSucceededLegacy++;
349 }
350 
incrementRefreshRateSwitches()351 void TimeStats::incrementRefreshRateSwitches() {
352     if (!mEnabled.load()) return;
353 
354     ATRACE_CALL();
355 
356     std::lock_guard<std::mutex> lock(mMutex);
357     mTimeStats.refreshRateSwitchesLegacy++;
358 }
359 
toMs(nsecs_t nanos)360 static int32_t toMs(nsecs_t nanos) {
361     int64_t millis =
362             std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::nanoseconds(nanos))
363                     .count();
364     millis = std::clamp(millis, int64_t(INT32_MIN), int64_t(INT32_MAX));
365     return static_cast<int32_t>(millis);
366 }
367 
msBetween(nsecs_t start,nsecs_t end)368 static int32_t msBetween(nsecs_t start, nsecs_t end) {
369     return toMs(end - start);
370 }
371 
recordFrameDuration(nsecs_t startTime,nsecs_t endTime)372 void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
373     if (!mEnabled.load()) return;
374 
375     std::lock_guard<std::mutex> lock(mMutex);
376     if (mPowerTime.powerMode == PowerMode::ON) {
377         mTimeStats.frameDurationLegacy.insert(msBetween(startTime, endTime));
378     }
379 }
380 
recordRenderEngineDuration(nsecs_t startTime,nsecs_t endTime)381 void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) {
382     if (!mEnabled.load()) return;
383 
384     std::lock_guard<std::mutex> lock(mMutex);
385     if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
386         ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
387         mGlobalRecord.renderEngineDurations.pop_front();
388     }
389     mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
390 }
391 
recordRenderEngineDuration(nsecs_t startTime,const std::shared_ptr<FenceTime> & endTime)392 void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
393                                            const std::shared_ptr<FenceTime>& endTime) {
394     if (!mEnabled.load()) return;
395 
396     std::lock_guard<std::mutex> lock(mMutex);
397     if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
398         ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
399         mGlobalRecord.renderEngineDurations.pop_front();
400     }
401     mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
402 }
403 
recordReadyLocked(int32_t layerId,TimeRecord * timeRecord)404 bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
405     if (!timeRecord->ready) {
406         ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
407               timeRecord->frameTime.frameNumber);
408         return false;
409     }
410 
411     if (timeRecord->acquireFence != nullptr) {
412         if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
413             return false;
414         }
415         if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
416             timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
417             timeRecord->acquireFence = nullptr;
418         } else {
419             ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerId,
420                   timeRecord->frameTime.frameNumber);
421         }
422     }
423 
424     if (timeRecord->presentFence != nullptr) {
425         if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
426             return false;
427         }
428         if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
429             timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
430             timeRecord->presentFence = nullptr;
431         } else {
432             ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerId,
433                   timeRecord->frameTime.frameNumber);
434         }
435     }
436 
437     return true;
438 }
439 
clampToNearestBucket(Fps fps,size_t bucketWidth)440 static int32_t clampToNearestBucket(Fps fps, size_t bucketWidth) {
441     return std::round(fps.getValue() / bucketWidth) * bucketWidth;
442 }
443 
flushAvailableRecordsToStatsLocked(int32_t layerId,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,GameMode gameMode)444 void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId, Fps displayRefreshRate,
445                                                    std::optional<Fps> renderRate,
446                                                    SetFrameRateVote frameRateVote,
447                                                    GameMode gameMode) {
448     ATRACE_CALL();
449     ALOGV("[%d]-flushAvailableRecordsToStatsLocked", layerId);
450 
451     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
452     TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
453     std::optional<int32_t>& prevPresentToPresentMs = layerRecord.prevPresentToPresentMs;
454     std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
455     const int32_t refreshRateBucket =
456             clampToNearestBucket(displayRefreshRate, REFRESH_RATE_BUCKET_WIDTH);
457     const int32_t renderRateBucket =
458             clampToNearestBucket(renderRate ? *renderRate : displayRefreshRate,
459                                  RENDER_RATE_BUCKET_WIDTH);
460     while (!timeRecords.empty()) {
461         if (!recordReadyLocked(layerId, &timeRecords[0])) break;
462         ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId,
463               timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
464 
465         if (prevTimeRecord.ready) {
466             uid_t uid = layerRecord.uid;
467             const std::string& layerName = layerRecord.layerName;
468             TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket};
469             if (!mTimeStats.stats.count(timelineKey)) {
470                 mTimeStats.stats[timelineKey].key = timelineKey;
471             }
472 
473             TimeStatsHelper::TimelineStats& displayStats = mTimeStats.stats[timelineKey];
474 
475             TimeStatsHelper::LayerStatsKey layerKey = {uid, layerName, gameMode};
476             if (!displayStats.stats.count(layerKey)) {
477                 displayStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket;
478                 displayStats.stats[layerKey].renderRateBucket = renderRateBucket;
479                 displayStats.stats[layerKey].uid = uid;
480                 displayStats.stats[layerKey].layerName = layerName;
481                 displayStats.stats[layerKey].gameMode = gameMode;
482             }
483             if (frameRateVote.frameRate > 0.0f) {
484                 displayStats.stats[layerKey].setFrameRateVote = frameRateVote;
485             }
486             TimeStatsHelper::TimeStatsLayer& timeStatsLayer = displayStats.stats[layerKey];
487             timeStatsLayer.totalFrames++;
488             timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
489             timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames;
490             timeStatsLayer.badDesiredPresentFrames += layerRecord.badDesiredPresentFrames;
491 
492             layerRecord.droppedFrames = 0;
493             layerRecord.lateAcquireFrames = 0;
494             layerRecord.badDesiredPresentFrames = 0;
495 
496             const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
497                                                       timeRecords[0].frameTime.acquireTime);
498             ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerId,
499                   timeRecords[0].frameTime.frameNumber, postToAcquireMs);
500             timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
501 
502             const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
503                                                       timeRecords[0].frameTime.presentTime);
504             ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerId,
505                   timeRecords[0].frameTime.frameNumber, postToPresentMs);
506             timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
507 
508             const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
509                                                          timeRecords[0].frameTime.presentTime);
510             ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerId,
511                   timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
512             timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
513 
514             const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
515                                                        timeRecords[0].frameTime.presentTime);
516             ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerId,
517                   timeRecords[0].frameTime.frameNumber, latchToPresentMs);
518             timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
519 
520             const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
521                                                          timeRecords[0].frameTime.presentTime);
522             ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerId,
523                   timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
524             timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
525 
526             const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
527                                                          timeRecords[0].frameTime.presentTime);
528             ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerId,
529                   timeRecords[0].frameTime.frameNumber, presentToPresentMs);
530             timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
531             if (prevPresentToPresentMs) {
532                 const int32_t presentToPresentDeltaMs =
533                         std::abs(presentToPresentMs - *prevPresentToPresentMs);
534                 timeStatsLayer.deltas["present2presentDelta"].insert(presentToPresentDeltaMs);
535             }
536             prevPresentToPresentMs = presentToPresentMs;
537         }
538         prevTimeRecord = timeRecords[0];
539         timeRecords.pop_front();
540         layerRecord.waitData--;
541     }
542 }
543 
544 static constexpr const char* kPopupWindowPrefix = "PopupWindow";
545 static const size_t kMinLenLayerName = std::strlen(kPopupWindowPrefix);
546 
547 // Avoid tracking the "PopupWindow:<random hash>#<number>" layers
layerNameIsValid(const std::string & layerName)548 static bool layerNameIsValid(const std::string& layerName) {
549     return layerName.length() >= kMinLenLayerName &&
550             layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0;
551 }
552 
canAddNewAggregatedStats(uid_t uid,const std::string & layerName,GameMode gameMode)553 bool TimeStats::canAddNewAggregatedStats(uid_t uid, const std::string& layerName,
554                                          GameMode gameMode) {
555     uint32_t layerRecords = 0;
556     for (const auto& record : mTimeStats.stats) {
557         if (record.second.stats.count({uid, layerName, gameMode}) > 0) {
558             return true;
559         }
560 
561         layerRecords += record.second.stats.size();
562     }
563 
564     return layerRecords < MAX_NUM_LAYER_STATS;
565 }
566 
setPostTime(int32_t layerId,uint64_t frameNumber,const std::string & layerName,uid_t uid,nsecs_t postTime,GameMode gameMode)567 void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
568                             uid_t uid, nsecs_t postTime, GameMode gameMode) {
569     if (!mEnabled.load()) return;
570 
571     ATRACE_CALL();
572     ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(),
573           postTime);
574 
575     std::lock_guard<std::mutex> lock(mMutex);
576     if (!canAddNewAggregatedStats(uid, layerName, gameMode)) {
577         return;
578     }
579     if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
580         layerNameIsValid(layerName)) {
581         mTimeStatsTracker[layerId].uid = uid;
582         mTimeStatsTracker[layerId].layerName = layerName;
583         mTimeStatsTracker[layerId].gameMode = gameMode;
584     }
585     if (!mTimeStatsTracker.count(layerId)) return;
586     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
587     if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
588         ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
589               layerId, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
590         mTimeStatsTracker.erase(layerId);
591         return;
592     }
593     // For most media content, the acquireFence is invalid because the buffer is
594     // ready at the queueBuffer stage. In this case, acquireTime should be given
595     // a default value as postTime.
596     TimeRecord timeRecord = {
597             .frameTime =
598                     {
599                             .frameNumber = frameNumber,
600                             .postTime = postTime,
601                             .latchTime = postTime,
602                             .acquireTime = postTime,
603                             .desiredTime = postTime,
604                     },
605     };
606     layerRecord.timeRecords.push_back(timeRecord);
607     if (layerRecord.waitData < 0 ||
608         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
609         layerRecord.waitData = layerRecord.timeRecords.size() - 1;
610 }
611 
setLatchTime(int32_t layerId,uint64_t frameNumber,nsecs_t latchTime)612 void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) {
613     if (!mEnabled.load()) return;
614 
615     ATRACE_CALL();
616     ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime);
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.latchTime = latchTime;
627     }
628 }
629 
incrementLatchSkipped(int32_t layerId,LatchSkipReason reason)630 void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) {
631     if (!mEnabled.load()) return;
632 
633     ATRACE_CALL();
634     ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId,
635           static_cast<std::underlying_type<LatchSkipReason>::type>(reason));
636 
637     std::lock_guard<std::mutex> lock(mMutex);
638     if (!mTimeStatsTracker.count(layerId)) return;
639     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
640 
641     switch (reason) {
642         case LatchSkipReason::LateAcquire:
643             layerRecord.lateAcquireFrames++;
644             break;
645     }
646 }
647 
incrementBadDesiredPresent(int32_t layerId)648 void TimeStats::incrementBadDesiredPresent(int32_t layerId) {
649     if (!mEnabled.load()) return;
650 
651     ATRACE_CALL();
652     ALOGV("[%d]-BadDesiredPresent", layerId);
653 
654     std::lock_guard<std::mutex> lock(mMutex);
655     if (!mTimeStatsTracker.count(layerId)) return;
656     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
657     layerRecord.badDesiredPresentFrames++;
658 }
659 
setDesiredTime(int32_t layerId,uint64_t frameNumber,nsecs_t desiredTime)660 void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
661     if (!mEnabled.load()) return;
662 
663     ATRACE_CALL();
664     ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime);
665 
666     std::lock_guard<std::mutex> lock(mMutex);
667     if (!mTimeStatsTracker.count(layerId)) return;
668     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
669     if (layerRecord.waitData < 0 ||
670         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
671         return;
672     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
673     if (timeRecord.frameTime.frameNumber == frameNumber) {
674         timeRecord.frameTime.desiredTime = desiredTime;
675     }
676 }
677 
setAcquireTime(int32_t layerId,uint64_t frameNumber,nsecs_t acquireTime)678 void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) {
679     if (!mEnabled.load()) return;
680 
681     ATRACE_CALL();
682     ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime);
683 
684     std::lock_guard<std::mutex> lock(mMutex);
685     if (!mTimeStatsTracker.count(layerId)) return;
686     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
687     if (layerRecord.waitData < 0 ||
688         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
689         return;
690     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
691     if (timeRecord.frameTime.frameNumber == frameNumber) {
692         timeRecord.frameTime.acquireTime = acquireTime;
693     }
694 }
695 
setAcquireFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & acquireFence)696 void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber,
697                                 const std::shared_ptr<FenceTime>& acquireFence) {
698     if (!mEnabled.load()) return;
699 
700     ATRACE_CALL();
701     ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber,
702           acquireFence->getSignalTime());
703 
704     std::lock_guard<std::mutex> lock(mMutex);
705     if (!mTimeStatsTracker.count(layerId)) return;
706     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
707     if (layerRecord.waitData < 0 ||
708         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
709         return;
710     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
711     if (timeRecord.frameTime.frameNumber == frameNumber) {
712         timeRecord.acquireFence = acquireFence;
713     }
714 }
715 
setPresentTime(int32_t layerId,uint64_t frameNumber,nsecs_t presentTime,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,GameMode gameMode)716 void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime,
717                                Fps displayRefreshRate, std::optional<Fps> renderRate,
718                                SetFrameRateVote frameRateVote, GameMode gameMode) {
719     if (!mEnabled.load()) return;
720 
721     ATRACE_CALL();
722     ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime);
723 
724     std::lock_guard<std::mutex> lock(mMutex);
725     if (!mTimeStatsTracker.count(layerId)) return;
726     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
727     if (layerRecord.waitData < 0 ||
728         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
729         return;
730     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
731     if (timeRecord.frameTime.frameNumber == frameNumber) {
732         timeRecord.frameTime.presentTime = presentTime;
733         timeRecord.ready = true;
734         layerRecord.waitData++;
735     }
736 
737     flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate, frameRateVote,
738                                        gameMode);
739 }
740 
setPresentFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & presentFence,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,GameMode gameMode)741 void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber,
742                                 const std::shared_ptr<FenceTime>& presentFence,
743                                 Fps displayRefreshRate, std::optional<Fps> renderRate,
744                                 SetFrameRateVote frameRateVote, GameMode gameMode) {
745     if (!mEnabled.load()) return;
746 
747     ATRACE_CALL();
748     ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber,
749           presentFence->getSignalTime());
750 
751     std::lock_guard<std::mutex> lock(mMutex);
752     if (!mTimeStatsTracker.count(layerId)) return;
753     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
754     if (layerRecord.waitData < 0 ||
755         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
756         return;
757     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
758     if (timeRecord.frameTime.frameNumber == frameNumber) {
759         timeRecord.presentFence = presentFence;
760         timeRecord.ready = true;
761         layerRecord.waitData++;
762     }
763 
764     flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate, frameRateVote,
765                                        gameMode);
766 }
767 
768 static const constexpr int32_t kValidJankyReason = JankType::DisplayHAL |
769         JankType::SurfaceFlingerCpuDeadlineMissed | JankType::SurfaceFlingerGpuDeadlineMissed |
770         JankType::AppDeadlineMissed | JankType::PredictionError |
771         JankType::SurfaceFlingerScheduling;
772 
773 template <class T>
updateJankPayload(T & t,int32_t reasons)774 static void updateJankPayload(T& t, int32_t reasons) {
775     t.jankPayload.totalFrames++;
776 
777     if (reasons & kValidJankyReason) {
778         t.jankPayload.totalJankyFrames++;
779         if ((reasons & JankType::SurfaceFlingerCpuDeadlineMissed) != 0) {
780             t.jankPayload.totalSFLongCpu++;
781         }
782         if ((reasons & JankType::SurfaceFlingerGpuDeadlineMissed) != 0) {
783             t.jankPayload.totalSFLongGpu++;
784         }
785         if ((reasons & JankType::DisplayHAL) != 0) {
786             t.jankPayload.totalSFUnattributed++;
787         }
788         if ((reasons & JankType::AppDeadlineMissed) != 0) {
789             t.jankPayload.totalAppUnattributed++;
790         }
791         if ((reasons & JankType::PredictionError) != 0) {
792             t.jankPayload.totalSFPredictionError++;
793         }
794         if ((reasons & JankType::SurfaceFlingerScheduling) != 0) {
795             t.jankPayload.totalSFScheduling++;
796         }
797     }
798 
799     // We want to track BufferStuffing separately as it can provide info on latency issues
800     if (reasons & JankType::BufferStuffing) {
801         t.jankPayload.totalAppBufferStuffing++;
802     }
803 }
804 
incrementJankyFrames(const JankyFramesInfo & info)805 void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) {
806     if (!mEnabled.load()) return;
807 
808     ATRACE_CALL();
809     std::lock_guard<std::mutex> lock(mMutex);
810 
811     // Only update layer stats if we're already tracking the layer in TimeStats.
812     // Otherwise, continue tracking the statistic but use a default layer name instead.
813     // As an implementation detail, we do this because this method is expected to be
814     // called from FrameTimeline, whose jank classification includes transaction jank
815     // that occurs without a buffer. But, in general those layer names are not suitable as
816     // aggregation keys: e.g., it's normal and expected for Window Manager to include the hash code
817     // for an animation leash. So while we can show that jank in dumpsys, aggregating based on the
818     // layer blows up the stats size, so as a workaround drop those stats. This assumes that
819     // TimeStats will flush the first present fence for a layer *before* FrameTimeline does so that
820     // the first jank record is not dropped.
821 
822     static const std::string kDefaultLayerName = "none";
823     constexpr GameMode kDefaultGameMode = GameMode::Unsupported;
824 
825     const int32_t refreshRateBucket =
826             clampToNearestBucket(info.refreshRate, REFRESH_RATE_BUCKET_WIDTH);
827     const int32_t renderRateBucket =
828             clampToNearestBucket(info.renderRate ? *info.renderRate : info.refreshRate,
829                                  RENDER_RATE_BUCKET_WIDTH);
830     const TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket};
831 
832     if (!mTimeStats.stats.count(timelineKey)) {
833         mTimeStats.stats[timelineKey].key = timelineKey;
834     }
835 
836     TimeStatsHelper::TimelineStats& timelineStats = mTimeStats.stats[timelineKey];
837 
838     updateJankPayload<TimeStatsHelper::TimelineStats>(timelineStats, info.reasons);
839 
840     TimeStatsHelper::LayerStatsKey layerKey = {info.uid, info.layerName, info.gameMode};
841     if (!timelineStats.stats.count(layerKey)) {
842         layerKey = {info.uid, kDefaultLayerName, kDefaultGameMode};
843         timelineStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket;
844         timelineStats.stats[layerKey].renderRateBucket = renderRateBucket;
845         timelineStats.stats[layerKey].uid = info.uid;
846         timelineStats.stats[layerKey].layerName = kDefaultLayerName;
847         timelineStats.stats[layerKey].gameMode = kDefaultGameMode;
848     }
849 
850     TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timelineStats.stats[layerKey];
851     updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, info.reasons);
852 
853     if (info.reasons & kValidJankyReason) {
854         // TimeStats Histograms only retain positive values, so we don't need to check if these
855         // deadlines were really missed if we know that the frame had jank, since deadlines
856         // that were met will be dropped.
857         timelineStats.displayDeadlineDeltas.insert(toMs(info.displayDeadlineDelta));
858         timelineStats.displayPresentDeltas.insert(toMs(info.displayPresentJitter));
859         timeStatsLayer.deltas["appDeadlineDeltas"].insert(toMs(info.appDeadlineDelta));
860     }
861 }
862 
onDestroy(int32_t layerId)863 void TimeStats::onDestroy(int32_t layerId) {
864     ATRACE_CALL();
865     ALOGV("[%d]-onDestroy", layerId);
866     std::lock_guard<std::mutex> lock(mMutex);
867     mTimeStatsTracker.erase(layerId);
868 }
869 
removeTimeRecord(int32_t layerId,uint64_t frameNumber)870 void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) {
871     if (!mEnabled.load()) return;
872 
873     ATRACE_CALL();
874     ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber);
875 
876     std::lock_guard<std::mutex> lock(mMutex);
877     if (!mTimeStatsTracker.count(layerId)) return;
878     LayerRecord& layerRecord = mTimeStatsTracker[layerId];
879     size_t removeAt = 0;
880     for (const TimeRecord& record : layerRecord.timeRecords) {
881         if (record.frameTime.frameNumber == frameNumber) break;
882         removeAt++;
883     }
884     if (removeAt == layerRecord.timeRecords.size()) return;
885     layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
886     if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
887         layerRecord.waitData--;
888     }
889     layerRecord.droppedFrames++;
890 }
891 
flushPowerTimeLocked()892 void TimeStats::flushPowerTimeLocked() {
893     if (!mEnabled.load()) return;
894 
895     nsecs_t curTime = systemTime();
896     // elapsedTime is in milliseconds.
897     int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
898 
899     switch (mPowerTime.powerMode) {
900         case PowerMode::ON:
901             mTimeStats.displayOnTimeLegacy += elapsedTime;
902             break;
903         case PowerMode::OFF:
904         case PowerMode::DOZE:
905         case PowerMode::DOZE_SUSPEND:
906         case PowerMode::ON_SUSPEND:
907         default:
908             break;
909     }
910 
911     mPowerTime.prevTime = curTime;
912 }
913 
setPowerMode(PowerMode powerMode)914 void TimeStats::setPowerMode(PowerMode powerMode) {
915     if (!mEnabled.load()) {
916         std::lock_guard<std::mutex> lock(mMutex);
917         mPowerTime.powerMode = powerMode;
918         return;
919     }
920 
921     std::lock_guard<std::mutex> lock(mMutex);
922     if (powerMode == mPowerTime.powerMode) return;
923 
924     flushPowerTimeLocked();
925     mPowerTime.powerMode = powerMode;
926 }
927 
recordRefreshRate(uint32_t fps,nsecs_t duration)928 void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
929     std::lock_guard<std::mutex> lock(mMutex);
930     if (mTimeStats.refreshRateStatsLegacy.count(fps)) {
931         mTimeStats.refreshRateStatsLegacy[fps] += duration;
932     } else {
933         mTimeStats.refreshRateStatsLegacy.insert({fps, duration});
934     }
935 }
936 
flushAvailableGlobalRecordsToStatsLocked()937 void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
938     ATRACE_CALL();
939 
940     while (!mGlobalRecord.presentFences.empty()) {
941         const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
942         if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
943 
944         if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
945             ALOGE("GlobalPresentFence is invalid!");
946             mGlobalRecord.prevPresentTime = 0;
947             mGlobalRecord.presentFences.pop_front();
948             continue;
949         }
950 
951         ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
952               mGlobalRecord.presentFences.front()->getSignalTime());
953 
954         if (mGlobalRecord.prevPresentTime != 0) {
955             const int32_t presentToPresentMs =
956                     msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
957             ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
958                   presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
959             mTimeStats.presentToPresentLegacy.insert(presentToPresentMs);
960         }
961 
962         mGlobalRecord.prevPresentTime = curPresentTime;
963         mGlobalRecord.presentFences.pop_front();
964     }
965     while (!mGlobalRecord.renderEngineDurations.empty()) {
966         const auto duration = mGlobalRecord.renderEngineDurations.front();
967         const auto& endTime = duration.endTime;
968 
969         nsecs_t endNs = -1;
970 
971         if (auto val = std::get_if<nsecs_t>(&endTime)) {
972             endNs = *val;
973         } else {
974             endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
975         }
976 
977         if (endNs == Fence::SIGNAL_TIME_PENDING) break;
978 
979         if (endNs < 0) {
980             ALOGE("RenderEngineTiming is invalid!");
981             mGlobalRecord.renderEngineDurations.pop_front();
982             continue;
983         }
984 
985         const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
986         mTimeStats.renderEngineTimingLegacy.insert(renderEngineMs);
987 
988         mGlobalRecord.renderEngineDurations.pop_front();
989     }
990 }
991 
setPresentFenceGlobal(const std::shared_ptr<FenceTime> & presentFence)992 void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
993     if (!mEnabled.load()) return;
994 
995     ATRACE_CALL();
996     std::lock_guard<std::mutex> lock(mMutex);
997     if (presentFence == nullptr || !presentFence->isValid()) {
998         mGlobalRecord.prevPresentTime = 0;
999         return;
1000     }
1001 
1002     if (mPowerTime.powerMode != PowerMode::ON) {
1003         // Try flushing the last present fence on PowerMode::ON.
1004         flushAvailableGlobalRecordsToStatsLocked();
1005         mGlobalRecord.presentFences.clear();
1006         mGlobalRecord.prevPresentTime = 0;
1007         return;
1008     }
1009 
1010     if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
1011         // The front presentFence must be trapped in pending status in this
1012         // case. Try dequeuing the front one to recover.
1013         ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
1014         mGlobalRecord.prevPresentTime = 0;
1015         mGlobalRecord.presentFences.pop_front();
1016     }
1017 
1018     mGlobalRecord.presentFences.emplace_back(presentFence);
1019     flushAvailableGlobalRecordsToStatsLocked();
1020 }
1021 
enable()1022 void TimeStats::enable() {
1023     if (mEnabled.load()) return;
1024 
1025     ATRACE_CALL();
1026 
1027     std::lock_guard<std::mutex> lock(mMutex);
1028     mEnabled.store(true);
1029     mTimeStats.statsStartLegacy = static_cast<int64_t>(std::time(0));
1030     mPowerTime.prevTime = systemTime();
1031     ALOGD("Enabled");
1032 }
1033 
disable()1034 void TimeStats::disable() {
1035     if (!mEnabled.load()) return;
1036 
1037     ATRACE_CALL();
1038 
1039     std::lock_guard<std::mutex> lock(mMutex);
1040     flushPowerTimeLocked();
1041     mEnabled.store(false);
1042     mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0));
1043     ALOGD("Disabled");
1044 }
1045 
clearAll()1046 void TimeStats::clearAll() {
1047     std::lock_guard<std::mutex> lock(mMutex);
1048     mTimeStats.stats.clear();
1049     clearGlobalLocked();
1050     clearLayersLocked();
1051 }
1052 
clearGlobalLocked()1053 void TimeStats::clearGlobalLocked() {
1054     ATRACE_CALL();
1055 
1056     mTimeStats.statsStartLegacy = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
1057     mTimeStats.statsEndLegacy = 0;
1058     mTimeStats.totalFramesLegacy = 0;
1059     mTimeStats.missedFramesLegacy = 0;
1060     mTimeStats.clientCompositionFramesLegacy = 0;
1061     mTimeStats.clientCompositionReusedFramesLegacy = 0;
1062     mTimeStats.compositionStrategyChangesLegacy = 0;
1063     mTimeStats.compositionStrategyPredictedLegacy = 0;
1064     mTimeStats.compositionStrategyPredictionSucceededLegacy = 0;
1065     mTimeStats.refreshRateSwitchesLegacy = 0;
1066     mTimeStats.displayOnTimeLegacy = 0;
1067     mTimeStats.presentToPresentLegacy.hist.clear();
1068     mTimeStats.frameDurationLegacy.hist.clear();
1069     mTimeStats.renderEngineTimingLegacy.hist.clear();
1070     mTimeStats.refreshRateStatsLegacy.clear();
1071     mPowerTime.prevTime = systemTime();
1072     for (auto& globalRecord : mTimeStats.stats) {
1073         globalRecord.second.clearGlobals();
1074     }
1075     mGlobalRecord.prevPresentTime = 0;
1076     mGlobalRecord.presentFences.clear();
1077     ALOGD("Cleared global stats");
1078 }
1079 
clearLayersLocked()1080 void TimeStats::clearLayersLocked() {
1081     ATRACE_CALL();
1082 
1083     mTimeStatsTracker.clear();
1084 
1085     for (auto& globalRecord : mTimeStats.stats) {
1086         globalRecord.second.stats.clear();
1087     }
1088     ALOGD("Cleared layer stats");
1089 }
1090 
isEnabled()1091 bool TimeStats::isEnabled() {
1092     return mEnabled.load();
1093 }
1094 
dump(bool asProto,std::optional<uint32_t> maxLayers,std::string & result)1095 void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
1096     ATRACE_CALL();
1097 
1098     std::lock_guard<std::mutex> lock(mMutex);
1099     if (mTimeStats.statsStartLegacy == 0) {
1100         return;
1101     }
1102 
1103     mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0));
1104 
1105     flushPowerTimeLocked();
1106 
1107     if (asProto) {
1108         ALOGD("Dumping TimeStats as proto");
1109         SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
1110         result.append(timeStatsProto.SerializeAsString());
1111     } else {
1112         ALOGD("Dumping TimeStats as text");
1113         result.append(mTimeStats.toString(maxLayers));
1114         result.append("\n");
1115     }
1116 }
1117 
1118 } // namespace impl
1119 
1120 } // namespace android
1121