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 #include <unordered_map>
18 #undef LOG_TAG
19 #define LOG_TAG "TimeStats"
20 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
21
22 #include <android-base/stringprintf.h>
23 #include <log/log.h>
24 #include <timestatsatomsproto/TimeStatsAtomsProtoHeader.h>
25 #include <utils/String8.h>
26 #include <utils/Timers.h>
27 #include <utils/Trace.h>
28
29 #include <algorithm>
30 #include <chrono>
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(int32_t gameMode)61 SurfaceflingerStatsLayerInfo_GameMode gameModeToProto(int32_t gameMode) {
62 switch (gameMode) {
63 case TimeStatsHelper::GameModeUnsupported:
64 return SurfaceflingerStatsLayerInfo::GAME_MODE_UNSUPPORTED;
65 case TimeStatsHelper::GameModeStandard:
66 return SurfaceflingerStatsLayerInfo::GAME_MODE_STANDARD;
67 case TimeStatsHelper::GameModePerformance:
68 return SurfaceflingerStatsLayerInfo::GAME_MODE_PERFORMANCE;
69 case TimeStatsHelper::GameModeBattery:
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
incrementClientCompositionFrames()324 void TimeStats::incrementClientCompositionFrames() {
325 if (!mEnabled.load()) return;
326
327 ATRACE_CALL();
328
329 std::lock_guard<std::mutex> lock(mMutex);
330 mTimeStats.clientCompositionFramesLegacy++;
331 }
332
incrementClientCompositionReusedFrames()333 void TimeStats::incrementClientCompositionReusedFrames() {
334 if (!mEnabled.load()) return;
335
336 ATRACE_CALL();
337
338 std::lock_guard<std::mutex> lock(mMutex);
339 mTimeStats.clientCompositionReusedFramesLegacy++;
340 }
341
incrementRefreshRateSwitches()342 void TimeStats::incrementRefreshRateSwitches() {
343 if (!mEnabled.load()) return;
344
345 ATRACE_CALL();
346
347 std::lock_guard<std::mutex> lock(mMutex);
348 mTimeStats.refreshRateSwitchesLegacy++;
349 }
350
incrementCompositionStrategyChanges()351 void TimeStats::incrementCompositionStrategyChanges() {
352 if (!mEnabled.load()) return;
353
354 ATRACE_CALL();
355
356 std::lock_guard<std::mutex> lock(mMutex);
357 mTimeStats.compositionStrategyChangesLegacy++;
358 }
359
recordDisplayEventConnectionCount(int32_t count)360 void TimeStats::recordDisplayEventConnectionCount(int32_t count) {
361 if (!mEnabled.load()) return;
362
363 ATRACE_CALL();
364
365 std::lock_guard<std::mutex> lock(mMutex);
366 mTimeStats.displayEventConnectionsCountLegacy =
367 std::max(mTimeStats.displayEventConnectionsCountLegacy, count);
368 }
369
toMs(nsecs_t nanos)370 static int32_t toMs(nsecs_t nanos) {
371 int64_t millis =
372 std::chrono::duration_cast<std::chrono::milliseconds>(std::chrono::nanoseconds(nanos))
373 .count();
374 millis = std::clamp(millis, int64_t(INT32_MIN), int64_t(INT32_MAX));
375 return static_cast<int32_t>(millis);
376 }
377
msBetween(nsecs_t start,nsecs_t end)378 static int32_t msBetween(nsecs_t start, nsecs_t end) {
379 return toMs(end - start);
380 }
381
recordFrameDuration(nsecs_t startTime,nsecs_t endTime)382 void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
383 if (!mEnabled.load()) return;
384
385 std::lock_guard<std::mutex> lock(mMutex);
386 if (mPowerTime.powerMode == PowerMode::ON) {
387 mTimeStats.frameDurationLegacy.insert(msBetween(startTime, endTime));
388 }
389 }
390
recordRenderEngineDuration(nsecs_t startTime,nsecs_t endTime)391 void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t 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
recordRenderEngineDuration(nsecs_t startTime,const std::shared_ptr<FenceTime> & endTime)402 void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
403 const std::shared_ptr<FenceTime>& endTime) {
404 if (!mEnabled.load()) return;
405
406 std::lock_guard<std::mutex> lock(mMutex);
407 if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
408 ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
409 mGlobalRecord.renderEngineDurations.pop_front();
410 }
411 mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
412 }
413
recordReadyLocked(int32_t layerId,TimeRecord * timeRecord)414 bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
415 if (!timeRecord->ready) {
416 ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
417 timeRecord->frameTime.frameNumber);
418 return false;
419 }
420
421 if (timeRecord->acquireFence != nullptr) {
422 if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
423 return false;
424 }
425 if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
426 timeRecord->frameTime.acquireTime = timeRecord->acquireFence->getSignalTime();
427 timeRecord->acquireFence = nullptr;
428 } else {
429 ALOGV("[%d]-[%" PRIu64 "]-acquireFence signal time is invalid", layerId,
430 timeRecord->frameTime.frameNumber);
431 }
432 }
433
434 if (timeRecord->presentFence != nullptr) {
435 if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
436 return false;
437 }
438 if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
439 timeRecord->frameTime.presentTime = timeRecord->presentFence->getSignalTime();
440 timeRecord->presentFence = nullptr;
441 } else {
442 ALOGV("[%d]-[%" PRIu64 "]-presentFence signal time invalid", layerId,
443 timeRecord->frameTime.frameNumber);
444 }
445 }
446
447 return true;
448 }
449
clampToNearestBucket(Fps fps,size_t bucketWidth)450 static int32_t clampToNearestBucket(Fps fps, size_t bucketWidth) {
451 return std::round(fps.getValue() / bucketWidth) * bucketWidth;
452 }
453
flushAvailableRecordsToStatsLocked(int32_t layerId,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,int32_t gameMode)454 void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId, Fps displayRefreshRate,
455 std::optional<Fps> renderRate,
456 SetFrameRateVote frameRateVote,
457 int32_t gameMode) {
458 ATRACE_CALL();
459 ALOGV("[%d]-flushAvailableRecordsToStatsLocked", layerId);
460
461 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
462 TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
463 std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
464 const int32_t refreshRateBucket =
465 clampToNearestBucket(displayRefreshRate, REFRESH_RATE_BUCKET_WIDTH);
466 const int32_t renderRateBucket =
467 clampToNearestBucket(renderRate ? *renderRate : displayRefreshRate,
468 RENDER_RATE_BUCKET_WIDTH);
469 while (!timeRecords.empty()) {
470 if (!recordReadyLocked(layerId, &timeRecords[0])) break;
471 ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId,
472 timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime);
473
474 if (prevTimeRecord.ready) {
475 uid_t uid = layerRecord.uid;
476 const std::string& layerName = layerRecord.layerName;
477 TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket};
478 if (!mTimeStats.stats.count(timelineKey)) {
479 mTimeStats.stats[timelineKey].key = timelineKey;
480 }
481
482 TimeStatsHelper::TimelineStats& displayStats = mTimeStats.stats[timelineKey];
483
484 TimeStatsHelper::LayerStatsKey layerKey = {uid, layerName, gameMode};
485 if (!displayStats.stats.count(layerKey)) {
486 displayStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket;
487 displayStats.stats[layerKey].renderRateBucket = renderRateBucket;
488 displayStats.stats[layerKey].uid = uid;
489 displayStats.stats[layerKey].layerName = layerName;
490 displayStats.stats[layerKey].gameMode = gameMode;
491 }
492 if (frameRateVote.frameRate > 0.0f) {
493 displayStats.stats[layerKey].setFrameRateVote = frameRateVote;
494 }
495 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = displayStats.stats[layerKey];
496 timeStatsLayer.totalFrames++;
497 timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
498 timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames;
499 timeStatsLayer.badDesiredPresentFrames += layerRecord.badDesiredPresentFrames;
500
501 layerRecord.droppedFrames = 0;
502 layerRecord.lateAcquireFrames = 0;
503 layerRecord.badDesiredPresentFrames = 0;
504
505 const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
506 timeRecords[0].frameTime.acquireTime);
507 ALOGV("[%d]-[%" PRIu64 "]-post2acquire[%d]", layerId,
508 timeRecords[0].frameTime.frameNumber, postToAcquireMs);
509 timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
510
511 const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
512 timeRecords[0].frameTime.presentTime);
513 ALOGV("[%d]-[%" PRIu64 "]-post2present[%d]", layerId,
514 timeRecords[0].frameTime.frameNumber, postToPresentMs);
515 timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
516
517 const int32_t acquireToPresentMs = msBetween(timeRecords[0].frameTime.acquireTime,
518 timeRecords[0].frameTime.presentTime);
519 ALOGV("[%d]-[%" PRIu64 "]-acquire2present[%d]", layerId,
520 timeRecords[0].frameTime.frameNumber, acquireToPresentMs);
521 timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
522
523 const int32_t latchToPresentMs = msBetween(timeRecords[0].frameTime.latchTime,
524 timeRecords[0].frameTime.presentTime);
525 ALOGV("[%d]-[%" PRIu64 "]-latch2present[%d]", layerId,
526 timeRecords[0].frameTime.frameNumber, latchToPresentMs);
527 timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
528
529 const int32_t desiredToPresentMs = msBetween(timeRecords[0].frameTime.desiredTime,
530 timeRecords[0].frameTime.presentTime);
531 ALOGV("[%d]-[%" PRIu64 "]-desired2present[%d]", layerId,
532 timeRecords[0].frameTime.frameNumber, desiredToPresentMs);
533 timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
534
535 const int32_t presentToPresentMs = msBetween(prevTimeRecord.frameTime.presentTime,
536 timeRecords[0].frameTime.presentTime);
537 ALOGV("[%d]-[%" PRIu64 "]-present2present[%d]", layerId,
538 timeRecords[0].frameTime.frameNumber, presentToPresentMs);
539 timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
540 }
541 prevTimeRecord = timeRecords[0];
542 timeRecords.pop_front();
543 layerRecord.waitData--;
544 }
545 }
546
547 static constexpr const char* kPopupWindowPrefix = "PopupWindow";
548 static const size_t kMinLenLayerName = std::strlen(kPopupWindowPrefix);
549
550 // Avoid tracking the "PopupWindow:<random hash>#<number>" layers
layerNameIsValid(const std::string & layerName)551 static bool layerNameIsValid(const std::string& layerName) {
552 return layerName.length() >= kMinLenLayerName &&
553 layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0;
554 }
555
canAddNewAggregatedStats(uid_t uid,const std::string & layerName,int32_t gameMode)556 bool TimeStats::canAddNewAggregatedStats(uid_t uid, const std::string& layerName,
557 int32_t gameMode) {
558 uint32_t layerRecords = 0;
559 for (const auto& record : mTimeStats.stats) {
560 if (record.second.stats.count({uid, layerName, gameMode}) > 0) {
561 return true;
562 }
563
564 layerRecords += record.second.stats.size();
565 }
566
567 return mTimeStats.stats.size() < MAX_NUM_LAYER_STATS;
568 }
569
setPostTime(int32_t layerId,uint64_t frameNumber,const std::string & layerName,uid_t uid,nsecs_t postTime,int32_t gameMode)570 void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
571 uid_t uid, nsecs_t postTime, int32_t gameMode) {
572 if (!mEnabled.load()) return;
573
574 ATRACE_CALL();
575 ALOGV("[%d]-[%" PRIu64 "]-[%s]-PostTime[%" PRId64 "]", layerId, frameNumber, layerName.c_str(),
576 postTime);
577
578 std::lock_guard<std::mutex> lock(mMutex);
579 if (!canAddNewAggregatedStats(uid, layerName, gameMode)) {
580 return;
581 }
582 if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS &&
583 layerNameIsValid(layerName)) {
584 mTimeStatsTracker[layerId].uid = uid;
585 mTimeStatsTracker[layerId].layerName = layerName;
586 mTimeStatsTracker[layerId].gameMode = gameMode;
587 }
588 if (!mTimeStatsTracker.count(layerId)) return;
589 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
590 if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
591 ALOGE("[%d]-[%s]-timeRecords is at its maximum size[%zu]. Ignore this when unittesting.",
592 layerId, layerRecord.layerName.c_str(), MAX_NUM_TIME_RECORDS);
593 mTimeStatsTracker.erase(layerId);
594 return;
595 }
596 // For most media content, the acquireFence is invalid because the buffer is
597 // ready at the queueBuffer stage. In this case, acquireTime should be given
598 // a default value as postTime.
599 TimeRecord timeRecord = {
600 .frameTime =
601 {
602 .frameNumber = frameNumber,
603 .postTime = postTime,
604 .latchTime = postTime,
605 .acquireTime = postTime,
606 .desiredTime = postTime,
607 },
608 };
609 layerRecord.timeRecords.push_back(timeRecord);
610 if (layerRecord.waitData < 0 ||
611 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
612 layerRecord.waitData = layerRecord.timeRecords.size() - 1;
613 }
614
setLatchTime(int32_t layerId,uint64_t frameNumber,nsecs_t latchTime)615 void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) {
616 if (!mEnabled.load()) return;
617
618 ATRACE_CALL();
619 ALOGV("[%d]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerId, frameNumber, latchTime);
620
621 std::lock_guard<std::mutex> lock(mMutex);
622 if (!mTimeStatsTracker.count(layerId)) return;
623 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
624 if (layerRecord.waitData < 0 ||
625 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
626 return;
627 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
628 if (timeRecord.frameTime.frameNumber == frameNumber) {
629 timeRecord.frameTime.latchTime = latchTime;
630 }
631 }
632
incrementLatchSkipped(int32_t layerId,LatchSkipReason reason)633 void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) {
634 if (!mEnabled.load()) return;
635
636 ATRACE_CALL();
637 ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId,
638 static_cast<std::underlying_type<LatchSkipReason>::type>(reason));
639
640 std::lock_guard<std::mutex> lock(mMutex);
641 if (!mTimeStatsTracker.count(layerId)) return;
642 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
643
644 switch (reason) {
645 case LatchSkipReason::LateAcquire:
646 layerRecord.lateAcquireFrames++;
647 break;
648 }
649 }
650
incrementBadDesiredPresent(int32_t layerId)651 void TimeStats::incrementBadDesiredPresent(int32_t layerId) {
652 if (!mEnabled.load()) return;
653
654 ATRACE_CALL();
655 ALOGV("[%d]-BadDesiredPresent", layerId);
656
657 std::lock_guard<std::mutex> lock(mMutex);
658 if (!mTimeStatsTracker.count(layerId)) return;
659 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
660 layerRecord.badDesiredPresentFrames++;
661 }
662
setDesiredTime(int32_t layerId,uint64_t frameNumber,nsecs_t desiredTime)663 void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
664 if (!mEnabled.load()) return;
665
666 ATRACE_CALL();
667 ALOGV("[%d]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerId, frameNumber, desiredTime);
668
669 std::lock_guard<std::mutex> lock(mMutex);
670 if (!mTimeStatsTracker.count(layerId)) return;
671 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
672 if (layerRecord.waitData < 0 ||
673 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
674 return;
675 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
676 if (timeRecord.frameTime.frameNumber == frameNumber) {
677 timeRecord.frameTime.desiredTime = desiredTime;
678 }
679 }
680
setAcquireTime(int32_t layerId,uint64_t frameNumber,nsecs_t acquireTime)681 void TimeStats::setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) {
682 if (!mEnabled.load()) return;
683
684 ATRACE_CALL();
685 ALOGV("[%d]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerId, frameNumber, acquireTime);
686
687 std::lock_guard<std::mutex> lock(mMutex);
688 if (!mTimeStatsTracker.count(layerId)) return;
689 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
690 if (layerRecord.waitData < 0 ||
691 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
692 return;
693 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
694 if (timeRecord.frameTime.frameNumber == frameNumber) {
695 timeRecord.frameTime.acquireTime = acquireTime;
696 }
697 }
698
setAcquireFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & acquireFence)699 void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber,
700 const std::shared_ptr<FenceTime>& acquireFence) {
701 if (!mEnabled.load()) return;
702
703 ATRACE_CALL();
704 ALOGV("[%d]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerId, frameNumber,
705 acquireFence->getSignalTime());
706
707 std::lock_guard<std::mutex> lock(mMutex);
708 if (!mTimeStatsTracker.count(layerId)) return;
709 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
710 if (layerRecord.waitData < 0 ||
711 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
712 return;
713 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
714 if (timeRecord.frameTime.frameNumber == frameNumber) {
715 timeRecord.acquireFence = acquireFence;
716 }
717 }
718
setPresentTime(int32_t layerId,uint64_t frameNumber,nsecs_t presentTime,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,int32_t gameMode)719 void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime,
720 Fps displayRefreshRate, std::optional<Fps> renderRate,
721 SetFrameRateVote frameRateVote, int32_t gameMode) {
722 if (!mEnabled.load()) return;
723
724 ATRACE_CALL();
725 ALOGV("[%d]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerId, frameNumber, presentTime);
726
727 std::lock_guard<std::mutex> lock(mMutex);
728 if (!mTimeStatsTracker.count(layerId)) return;
729 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
730 if (layerRecord.waitData < 0 ||
731 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
732 return;
733 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
734 if (timeRecord.frameTime.frameNumber == frameNumber) {
735 timeRecord.frameTime.presentTime = presentTime;
736 timeRecord.ready = true;
737 layerRecord.waitData++;
738 }
739
740 flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate, frameRateVote,
741 gameMode);
742 }
743
setPresentFence(int32_t layerId,uint64_t frameNumber,const std::shared_ptr<FenceTime> & presentFence,Fps displayRefreshRate,std::optional<Fps> renderRate,SetFrameRateVote frameRateVote,int32_t gameMode)744 void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber,
745 const std::shared_ptr<FenceTime>& presentFence,
746 Fps displayRefreshRate, std::optional<Fps> renderRate,
747 SetFrameRateVote frameRateVote, int32_t gameMode) {
748 if (!mEnabled.load()) return;
749
750 ATRACE_CALL();
751 ALOGV("[%d]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerId, frameNumber,
752 presentFence->getSignalTime());
753
754 std::lock_guard<std::mutex> lock(mMutex);
755 if (!mTimeStatsTracker.count(layerId)) return;
756 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
757 if (layerRecord.waitData < 0 ||
758 layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
759 return;
760 TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
761 if (timeRecord.frameTime.frameNumber == frameNumber) {
762 timeRecord.presentFence = presentFence;
763 timeRecord.ready = true;
764 layerRecord.waitData++;
765 }
766
767 flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate, frameRateVote,
768 gameMode);
769 }
770
771 static const constexpr int32_t kValidJankyReason = JankType::DisplayHAL |
772 JankType::SurfaceFlingerCpuDeadlineMissed | JankType::SurfaceFlingerGpuDeadlineMissed |
773 JankType::AppDeadlineMissed | JankType::PredictionError |
774 JankType::SurfaceFlingerScheduling;
775
776 template <class T>
updateJankPayload(T & t,int32_t reasons)777 static void updateJankPayload(T& t, int32_t reasons) {
778 t.jankPayload.totalFrames++;
779
780 if (reasons & kValidJankyReason) {
781 t.jankPayload.totalJankyFrames++;
782 if ((reasons & JankType::SurfaceFlingerCpuDeadlineMissed) != 0) {
783 t.jankPayload.totalSFLongCpu++;
784 }
785 if ((reasons & JankType::SurfaceFlingerGpuDeadlineMissed) != 0) {
786 t.jankPayload.totalSFLongGpu++;
787 }
788 if ((reasons & JankType::DisplayHAL) != 0) {
789 t.jankPayload.totalSFUnattributed++;
790 }
791 if ((reasons & JankType::AppDeadlineMissed) != 0) {
792 t.jankPayload.totalAppUnattributed++;
793 }
794 if ((reasons & JankType::PredictionError) != 0) {
795 t.jankPayload.totalSFPredictionError++;
796 }
797 if ((reasons & JankType::SurfaceFlingerScheduling) != 0) {
798 t.jankPayload.totalSFScheduling++;
799 }
800 }
801
802 // We want to track BufferStuffing separately as it can provide info on latency issues
803 if (reasons & JankType::BufferStuffing) {
804 t.jankPayload.totalAppBufferStuffing++;
805 }
806 }
807
incrementJankyFrames(const JankyFramesInfo & info)808 void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) {
809 if (!mEnabled.load()) return;
810
811 ATRACE_CALL();
812 std::lock_guard<std::mutex> lock(mMutex);
813
814 // Only update layer stats if we're already tracking the layer in TimeStats.
815 // Otherwise, continue tracking the statistic but use a default layer name instead.
816 // As an implementation detail, we do this because this method is expected to be
817 // called from FrameTimeline, whose jank classification includes transaction jank
818 // that occurs without a buffer. But, in general those layer names are not suitable as
819 // aggregation keys: e.g., it's normal and expected for Window Manager to include the hash code
820 // for an animation leash. So while we can show that jank in dumpsys, aggregating based on the
821 // layer blows up the stats size, so as a workaround drop those stats. This assumes that
822 // TimeStats will flush the first present fence for a layer *before* FrameTimeline does so that
823 // the first jank record is not dropped.
824
825 static const std::string kDefaultLayerName = "none";
826 static constexpr int32_t kDefaultGameMode = TimeStatsHelper::GameModeUnsupported;
827
828 const int32_t refreshRateBucket =
829 clampToNearestBucket(info.refreshRate, REFRESH_RATE_BUCKET_WIDTH);
830 const int32_t renderRateBucket =
831 clampToNearestBucket(info.renderRate ? *info.renderRate : info.refreshRate,
832 RENDER_RATE_BUCKET_WIDTH);
833 const TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket};
834
835 if (!mTimeStats.stats.count(timelineKey)) {
836 mTimeStats.stats[timelineKey].key = timelineKey;
837 }
838
839 TimeStatsHelper::TimelineStats& timelineStats = mTimeStats.stats[timelineKey];
840
841 updateJankPayload<TimeStatsHelper::TimelineStats>(timelineStats, info.reasons);
842
843 TimeStatsHelper::LayerStatsKey layerKey = {info.uid, info.layerName, info.gameMode};
844 if (!timelineStats.stats.count(layerKey)) {
845 layerKey = {info.uid, kDefaultLayerName, kDefaultGameMode};
846 timelineStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket;
847 timelineStats.stats[layerKey].renderRateBucket = renderRateBucket;
848 timelineStats.stats[layerKey].uid = info.uid;
849 timelineStats.stats[layerKey].layerName = kDefaultLayerName;
850 timelineStats.stats[layerKey].gameMode = kDefaultGameMode;
851 }
852
853 TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timelineStats.stats[layerKey];
854 updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, info.reasons);
855
856 if (info.reasons & kValidJankyReason) {
857 // TimeStats Histograms only retain positive values, so we don't need to check if these
858 // deadlines were really missed if we know that the frame had jank, since deadlines
859 // that were met will be dropped.
860 timelineStats.displayDeadlineDeltas.insert(toMs(info.displayDeadlineDelta));
861 timelineStats.displayPresentDeltas.insert(toMs(info.displayPresentJitter));
862 timeStatsLayer.deltas["appDeadlineDeltas"].insert(toMs(info.appDeadlineDelta));
863 }
864 }
865
onDestroy(int32_t layerId)866 void TimeStats::onDestroy(int32_t layerId) {
867 ATRACE_CALL();
868 ALOGV("[%d]-onDestroy", layerId);
869 std::lock_guard<std::mutex> lock(mMutex);
870 mTimeStatsTracker.erase(layerId);
871 }
872
removeTimeRecord(int32_t layerId,uint64_t frameNumber)873 void TimeStats::removeTimeRecord(int32_t layerId, uint64_t frameNumber) {
874 if (!mEnabled.load()) return;
875
876 ATRACE_CALL();
877 ALOGV("[%d]-[%" PRIu64 "]-removeTimeRecord", layerId, frameNumber);
878
879 std::lock_guard<std::mutex> lock(mMutex);
880 if (!mTimeStatsTracker.count(layerId)) return;
881 LayerRecord& layerRecord = mTimeStatsTracker[layerId];
882 size_t removeAt = 0;
883 for (const TimeRecord& record : layerRecord.timeRecords) {
884 if (record.frameTime.frameNumber == frameNumber) break;
885 removeAt++;
886 }
887 if (removeAt == layerRecord.timeRecords.size()) return;
888 layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
889 if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
890 layerRecord.waitData--;
891 }
892 layerRecord.droppedFrames++;
893 }
894
flushPowerTimeLocked()895 void TimeStats::flushPowerTimeLocked() {
896 if (!mEnabled.load()) return;
897
898 nsecs_t curTime = systemTime();
899 // elapsedTime is in milliseconds.
900 int64_t elapsedTime = (curTime - mPowerTime.prevTime) / 1000000;
901
902 switch (mPowerTime.powerMode) {
903 case PowerMode::ON:
904 mTimeStats.displayOnTimeLegacy += elapsedTime;
905 break;
906 case PowerMode::OFF:
907 case PowerMode::DOZE:
908 case PowerMode::DOZE_SUSPEND:
909 case PowerMode::ON_SUSPEND:
910 default:
911 break;
912 }
913
914 mPowerTime.prevTime = curTime;
915 }
916
setPowerMode(PowerMode powerMode)917 void TimeStats::setPowerMode(PowerMode powerMode) {
918 if (!mEnabled.load()) {
919 std::lock_guard<std::mutex> lock(mMutex);
920 mPowerTime.powerMode = powerMode;
921 return;
922 }
923
924 std::lock_guard<std::mutex> lock(mMutex);
925 if (powerMode == mPowerTime.powerMode) return;
926
927 flushPowerTimeLocked();
928 mPowerTime.powerMode = powerMode;
929 }
930
recordRefreshRate(uint32_t fps,nsecs_t duration)931 void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) {
932 std::lock_guard<std::mutex> lock(mMutex);
933 if (mTimeStats.refreshRateStatsLegacy.count(fps)) {
934 mTimeStats.refreshRateStatsLegacy[fps] += duration;
935 } else {
936 mTimeStats.refreshRateStatsLegacy.insert({fps, duration});
937 }
938 }
939
flushAvailableGlobalRecordsToStatsLocked()940 void TimeStats::flushAvailableGlobalRecordsToStatsLocked() {
941 ATRACE_CALL();
942
943 while (!mGlobalRecord.presentFences.empty()) {
944 const nsecs_t curPresentTime = mGlobalRecord.presentFences.front()->getSignalTime();
945 if (curPresentTime == Fence::SIGNAL_TIME_PENDING) break;
946
947 if (curPresentTime == Fence::SIGNAL_TIME_INVALID) {
948 ALOGE("GlobalPresentFence is invalid!");
949 mGlobalRecord.prevPresentTime = 0;
950 mGlobalRecord.presentFences.pop_front();
951 continue;
952 }
953
954 ALOGV("GlobalPresentFenceTime[%" PRId64 "]",
955 mGlobalRecord.presentFences.front()->getSignalTime());
956
957 if (mGlobalRecord.prevPresentTime != 0) {
958 const int32_t presentToPresentMs =
959 msBetween(mGlobalRecord.prevPresentTime, curPresentTime);
960 ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]",
961 presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime);
962 mTimeStats.presentToPresentLegacy.insert(presentToPresentMs);
963 }
964
965 mGlobalRecord.prevPresentTime = curPresentTime;
966 mGlobalRecord.presentFences.pop_front();
967 }
968 while (!mGlobalRecord.renderEngineDurations.empty()) {
969 const auto duration = mGlobalRecord.renderEngineDurations.front();
970 const auto& endTime = duration.endTime;
971
972 nsecs_t endNs = -1;
973
974 if (auto val = std::get_if<nsecs_t>(&endTime)) {
975 endNs = *val;
976 } else {
977 endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
978 }
979
980 if (endNs == Fence::SIGNAL_TIME_PENDING) break;
981
982 if (endNs < 0) {
983 ALOGE("RenderEngineTiming is invalid!");
984 mGlobalRecord.renderEngineDurations.pop_front();
985 continue;
986 }
987
988 const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
989 mTimeStats.renderEngineTimingLegacy.insert(renderEngineMs);
990
991 mGlobalRecord.renderEngineDurations.pop_front();
992 }
993 }
994
setPresentFenceGlobal(const std::shared_ptr<FenceTime> & presentFence)995 void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
996 if (!mEnabled.load()) return;
997
998 ATRACE_CALL();
999 std::lock_guard<std::mutex> lock(mMutex);
1000 if (presentFence == nullptr || !presentFence->isValid()) {
1001 mGlobalRecord.prevPresentTime = 0;
1002 return;
1003 }
1004
1005 if (mPowerTime.powerMode != PowerMode::ON) {
1006 // Try flushing the last present fence on PowerMode::ON.
1007 flushAvailableGlobalRecordsToStatsLocked();
1008 mGlobalRecord.presentFences.clear();
1009 mGlobalRecord.prevPresentTime = 0;
1010 return;
1011 }
1012
1013 if (mGlobalRecord.presentFences.size() == MAX_NUM_TIME_RECORDS) {
1014 // The front presentFence must be trapped in pending status in this
1015 // case. Try dequeuing the front one to recover.
1016 ALOGE("GlobalPresentFences is already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
1017 mGlobalRecord.prevPresentTime = 0;
1018 mGlobalRecord.presentFences.pop_front();
1019 }
1020
1021 mGlobalRecord.presentFences.emplace_back(presentFence);
1022 flushAvailableGlobalRecordsToStatsLocked();
1023 }
1024
enable()1025 void TimeStats::enable() {
1026 if (mEnabled.load()) return;
1027
1028 ATRACE_CALL();
1029
1030 std::lock_guard<std::mutex> lock(mMutex);
1031 mEnabled.store(true);
1032 mTimeStats.statsStartLegacy = static_cast<int64_t>(std::time(0));
1033 mPowerTime.prevTime = systemTime();
1034 ALOGD("Enabled");
1035 }
1036
disable()1037 void TimeStats::disable() {
1038 if (!mEnabled.load()) return;
1039
1040 ATRACE_CALL();
1041
1042 std::lock_guard<std::mutex> lock(mMutex);
1043 flushPowerTimeLocked();
1044 mEnabled.store(false);
1045 mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0));
1046 ALOGD("Disabled");
1047 }
1048
clearAll()1049 void TimeStats::clearAll() {
1050 std::lock_guard<std::mutex> lock(mMutex);
1051 mTimeStats.stats.clear();
1052 clearGlobalLocked();
1053 clearLayersLocked();
1054 }
1055
clearGlobalLocked()1056 void TimeStats::clearGlobalLocked() {
1057 ATRACE_CALL();
1058
1059 mTimeStats.statsStartLegacy = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
1060 mTimeStats.statsEndLegacy = 0;
1061 mTimeStats.totalFramesLegacy = 0;
1062 mTimeStats.missedFramesLegacy = 0;
1063 mTimeStats.clientCompositionFramesLegacy = 0;
1064 mTimeStats.clientCompositionReusedFramesLegacy = 0;
1065 mTimeStats.refreshRateSwitchesLegacy = 0;
1066 mTimeStats.compositionStrategyChangesLegacy = 0;
1067 mTimeStats.displayEventConnectionsCountLegacy = 0;
1068 mTimeStats.displayOnTimeLegacy = 0;
1069 mTimeStats.presentToPresentLegacy.hist.clear();
1070 mTimeStats.frameDurationLegacy.hist.clear();
1071 mTimeStats.renderEngineTimingLegacy.hist.clear();
1072 mTimeStats.refreshRateStatsLegacy.clear();
1073 mPowerTime.prevTime = systemTime();
1074 for (auto& globalRecord : mTimeStats.stats) {
1075 globalRecord.second.clearGlobals();
1076 }
1077 mGlobalRecord.prevPresentTime = 0;
1078 mGlobalRecord.presentFences.clear();
1079 ALOGD("Cleared global stats");
1080 }
1081
clearLayersLocked()1082 void TimeStats::clearLayersLocked() {
1083 ATRACE_CALL();
1084
1085 mTimeStatsTracker.clear();
1086
1087 for (auto& globalRecord : mTimeStats.stats) {
1088 globalRecord.second.stats.clear();
1089 }
1090 ALOGD("Cleared layer stats");
1091 }
1092
isEnabled()1093 bool TimeStats::isEnabled() {
1094 return mEnabled.load();
1095 }
1096
dump(bool asProto,std::optional<uint32_t> maxLayers,std::string & result)1097 void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::string& result) {
1098 ATRACE_CALL();
1099
1100 std::lock_guard<std::mutex> lock(mMutex);
1101 if (mTimeStats.statsStartLegacy == 0) {
1102 return;
1103 }
1104
1105 mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0));
1106
1107 flushPowerTimeLocked();
1108
1109 if (asProto) {
1110 ALOGD("Dumping TimeStats as proto");
1111 SFTimeStatsGlobalProto timeStatsProto = mTimeStats.toProto(maxLayers);
1112 result.append(timeStatsProto.SerializeAsString());
1113 } else {
1114 ALOGD("Dumping TimeStats as text");
1115 result.append(mTimeStats.toString(maxLayers));
1116 result.append("\n");
1117 }
1118 }
1119
1120 } // namespace impl
1121
1122 } // namespace android
1123