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