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 #undef LOG_TAG
17 #define LOG_TAG "TimeStats"
18 #define ATRACE_TAG ATRACE_TAG_GRAPHICS
19 
20 #include "TimeStats.h"
21 
22 #include <android-base/stringprintf.h>
23 
24 #include <log/log.h>
25 
26 #include <utils/String8.h>
27 #include <utils/Trace.h>
28 
29 #include <algorithm>
30 #include <regex>
31 
32 namespace android {
33 
getInstance()34 TimeStats& TimeStats::getInstance() {
35     static std::unique_ptr<TimeStats> sInstance;
36     static std::once_flag sOnceFlag;
37 
38     std::call_once(sOnceFlag, [] { sInstance.reset(new TimeStats); });
39     return *sInstance.get();
40 }
41 
parseArgs(bool asProto,const Vector<String16> & args,size_t & index,String8 & result)42 void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, size_t& index,
43                           String8& result) {
44     ATRACE_CALL();
45 
46     if (args.size() > index + 10) {
47         ALOGD("Invalid args count");
48         return;
49     }
50 
51     std::unordered_map<std::string, int32_t> argsMap;
52     while (index < args.size()) {
53         argsMap[std::string(String8(args[index]).c_str())] = index;
54         ++index;
55     }
56 
57     if (argsMap.count("-disable")) {
58         disable();
59     }
60 
61     if (argsMap.count("-dump")) {
62         std::optional<uint32_t> maxLayers = std::nullopt;
63         auto iter = argsMap.find("-maxlayers");
64         if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
65             int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
66             value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
67             maxLayers = static_cast<uint32_t>(value);
68         }
69 
70         dump(asProto, maxLayers, result);
71     }
72 
73     if (argsMap.count("-clear")) {
74         clear();
75     }
76 
77     if (argsMap.count("-enable")) {
78         enable();
79     }
80 }
81 
incrementTotalFrames()82 void TimeStats::incrementTotalFrames() {
83     if (!mEnabled.load()) return;
84 
85     ATRACE_CALL();
86 
87     std::lock_guard<std::mutex> lock(mMutex);
88     timeStats.totalFrames++;
89 }
90 
incrementMissedFrames()91 void TimeStats::incrementMissedFrames() {
92     if (!mEnabled.load()) return;
93 
94     ATRACE_CALL();
95 
96     std::lock_guard<std::mutex> lock(mMutex);
97     timeStats.missedFrames++;
98 }
99 
incrementClientCompositionFrames()100 void TimeStats::incrementClientCompositionFrames() {
101     if (!mEnabled.load()) return;
102 
103     ATRACE_CALL();
104 
105     std::lock_guard<std::mutex> lock(mMutex);
106     timeStats.clientCompositionFrames++;
107 }
108 
recordReadyLocked(const std::string & layerName,TimeRecord * timeRecord)109 bool TimeStats::recordReadyLocked(const std::string& layerName, TimeRecord* timeRecord) {
110     if (!timeRecord->ready) {
111         ALOGV("[%s]-[%" PRIu64 "]-presentFence is still not received", layerName.c_str(),
112               timeRecord->frameNumber);
113         return false;
114     }
115 
116     if (timeRecord->acquireFence != nullptr) {
117         if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
118             return false;
119         }
120         if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
121             timeRecord->acquireTime = timeRecord->acquireFence->getSignalTime();
122             timeRecord->acquireFence = nullptr;
123         } else {
124             ALOGV("[%s]-[%" PRIu64 "]-acquireFence signal time is invalid", layerName.c_str(),
125                   timeRecord->frameNumber);
126         }
127     }
128 
129     if (timeRecord->presentFence != nullptr) {
130         if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
131             return false;
132         }
133         if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
134             timeRecord->presentTime = timeRecord->presentFence->getSignalTime();
135             timeRecord->presentFence = nullptr;
136         } else {
137             ALOGV("[%s]-[%" PRIu64 "]-presentFence signal time invalid", layerName.c_str(),
138                   timeRecord->frameNumber);
139         }
140     }
141 
142     return true;
143 }
144 
msBetween(nsecs_t start,nsecs_t end)145 static int32_t msBetween(nsecs_t start, nsecs_t end) {
146     int64_t delta = (end - start) / 1000000;
147     delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
148     return static_cast<int32_t>(delta);
149 }
150 
getPackageName(const std::string & layerName)151 static std::string getPackageName(const std::string& layerName) {
152     // This regular expression captures the following for instance:
153     // StatusBar in StatusBar#0
154     // com.appname in com.appname/com.appname.activity#0
155     // com.appname in SurfaceView - com.appname/com.appname.activity#0
156     const std::regex re("(?:SurfaceView[-\\s\\t]+)?([^/]+).*#\\d+");
157     std::smatch match;
158     if (std::regex_match(layerName.begin(), layerName.end(), match, re)) {
159         // There must be a match for group 1 otherwise the whole string is not
160         // matched and the above will return false
161         return match[1];
162     }
163     return "";
164 }
165 
flushAvailableRecordsToStatsLocked(const std::string & layerName)166 void TimeStats::flushAvailableRecordsToStatsLocked(const std::string& layerName) {
167     ATRACE_CALL();
168 
169     LayerRecord& layerRecord = timeStatsTracker[layerName];
170     TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
171     std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
172     while (!timeRecords.empty()) {
173         if (!recordReadyLocked(layerName, &timeRecords[0])) break;
174         ALOGV("[%s]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerName.c_str(),
175               timeRecords[0].frameNumber, timeRecords[0].presentTime);
176 
177         if (prevTimeRecord.ready) {
178             if (!timeStats.stats.count(layerName)) {
179                 timeStats.stats[layerName].layerName = layerName;
180                 timeStats.stats[layerName].packageName = getPackageName(layerName);
181                 timeStats.stats[layerName].statsStart = static_cast<int64_t>(std::time(0));
182             }
183             TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timeStats.stats[layerName];
184             timeStatsLayer.totalFrames++;
185 
186             const int32_t postToPresentMs =
187                     msBetween(timeRecords[0].postTime, timeRecords[0].presentTime);
188             ALOGV("[%s]-[%" PRIu64 "]-post2present[%d]", layerName.c_str(),
189                   timeRecords[0].frameNumber, postToPresentMs);
190             timeStatsLayer.deltas["post2present"].insert(postToPresentMs);
191 
192             const int32_t acquireToPresentMs =
193                     msBetween(timeRecords[0].acquireTime, timeRecords[0].presentTime);
194             ALOGV("[%s]-[%" PRIu64 "]-acquire2present[%d]", layerName.c_str(),
195                   timeRecords[0].frameNumber, acquireToPresentMs);
196             timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);
197 
198             const int32_t latchToPresentMs =
199                     msBetween(timeRecords[0].latchTime, timeRecords[0].presentTime);
200             ALOGV("[%s]-[%" PRIu64 "]-latch2present[%d]", layerName.c_str(),
201                   timeRecords[0].frameNumber, latchToPresentMs);
202             timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);
203 
204             const int32_t desiredToPresentMs =
205                     msBetween(timeRecords[0].desiredTime, timeRecords[0].presentTime);
206             ALOGV("[%s]-[%" PRIu64 "]-desired2present[%d]", layerName.c_str(),
207                   timeRecords[0].frameNumber, desiredToPresentMs);
208             timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);
209 
210             const int32_t presentToPresentMs =
211                     msBetween(prevTimeRecord.presentTime, timeRecords[0].presentTime);
212             ALOGV("[%s]-[%" PRIu64 "]-present2present[%d]", layerName.c_str(),
213                   timeRecords[0].frameNumber, presentToPresentMs);
214             timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
215 
216             timeStats.stats[layerName].statsEnd = static_cast<int64_t>(std::time(0));
217         }
218         prevTimeRecord = timeRecords[0];
219         timeRecords.pop_front();
220         layerRecord.waitData--;
221     }
222 }
223 
layerNameIsValid(const std::string & layerName)224 static bool layerNameIsValid(const std::string& layerName) {
225     // This regular expression captures the following layer names for instance:
226     // 1) StatusBat#0
227     // 2) NavigationBar#1
228     // 3) com.*#0
229     // 4) SurfaceView - com.*#0
230     // Using [-\\s\t]+ for the conjunction part between SurfaceView and com.* is
231     // a bit more robust in case there's a slight change.
232     // The layer name would only consist of . / $ _ 0-9 a-z A-Z in most cases.
233     std::regex re("(((SurfaceView[-\\s\\t]+)?com\\.[./$\\w]+)|((Status|Navigation)Bar))#\\d+");
234     return std::regex_match(layerName.begin(), layerName.end(), re);
235 }
236 
setPostTime(const std::string & layerName,uint64_t frameNumber,nsecs_t postTime)237 void TimeStats::setPostTime(const std::string& layerName, uint64_t frameNumber, nsecs_t postTime) {
238     if (!mEnabled.load()) return;
239 
240     ATRACE_CALL();
241     ALOGV("[%s]-[%" PRIu64 "]-PostTime[%" PRId64 "]", layerName.c_str(), frameNumber, postTime);
242 
243     std::lock_guard<std::mutex> lock(mMutex);
244     if (!timeStatsTracker.count(layerName) && !layerNameIsValid(layerName)) {
245         return;
246     }
247     LayerRecord& layerRecord = timeStatsTracker[layerName];
248     if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
249         ALOGV("[%s]-timeRecords is already at its maximum size[%zu]", layerName.c_str(),
250               MAX_NUM_TIME_RECORDS);
251         // TODO(zzyiwei): if this happens, there must be a present fence missing
252         // or waitData is not in the correct position. Need to think out a
253         // reasonable way to recover from this state.
254         return;
255     }
256     // For most media content, the acquireFence is invalid because the buffer is
257     // ready at the queueBuffer stage. In this case, acquireTime should be given
258     // a default value as postTime.
259     TimeRecord timeRecord = {
260             .frameNumber = frameNumber,
261             .postTime = postTime,
262             .acquireTime = postTime,
263     };
264     layerRecord.timeRecords.push_back(timeRecord);
265     if (layerRecord.waitData < 0 ||
266         layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
267         layerRecord.waitData = layerRecord.timeRecords.size() - 1;
268 }
269 
setLatchTime(const std::string & layerName,uint64_t frameNumber,nsecs_t latchTime)270 void TimeStats::setLatchTime(const std::string& layerName, uint64_t frameNumber,
271                              nsecs_t latchTime) {
272     if (!mEnabled.load()) return;
273 
274     ATRACE_CALL();
275     ALOGV("[%s]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerName.c_str(), frameNumber, latchTime);
276 
277     std::lock_guard<std::mutex> lock(mMutex);
278     if (!timeStatsTracker.count(layerName)) return;
279     LayerRecord& layerRecord = timeStatsTracker[layerName];
280     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
281     if (timeRecord.frameNumber == frameNumber) {
282         timeRecord.latchTime = latchTime;
283     }
284 }
285 
setDesiredTime(const std::string & layerName,uint64_t frameNumber,nsecs_t desiredTime)286 void TimeStats::setDesiredTime(const std::string& layerName, uint64_t frameNumber,
287                                nsecs_t desiredTime) {
288     if (!mEnabled.load()) return;
289 
290     ATRACE_CALL();
291     ALOGV("[%s]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerName.c_str(), frameNumber,
292           desiredTime);
293 
294     std::lock_guard<std::mutex> lock(mMutex);
295     if (!timeStatsTracker.count(layerName)) return;
296     LayerRecord& layerRecord = timeStatsTracker[layerName];
297     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
298     if (timeRecord.frameNumber == frameNumber) {
299         timeRecord.desiredTime = desiredTime;
300     }
301 }
302 
setAcquireTime(const std::string & layerName,uint64_t frameNumber,nsecs_t acquireTime)303 void TimeStats::setAcquireTime(const std::string& layerName, uint64_t frameNumber,
304                                nsecs_t acquireTime) {
305     if (!mEnabled.load()) return;
306 
307     ATRACE_CALL();
308     ALOGV("[%s]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerName.c_str(), frameNumber,
309           acquireTime);
310 
311     std::lock_guard<std::mutex> lock(mMutex);
312     if (!timeStatsTracker.count(layerName)) return;
313     LayerRecord& layerRecord = timeStatsTracker[layerName];
314     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
315     if (timeRecord.frameNumber == frameNumber) {
316         timeRecord.acquireTime = acquireTime;
317     }
318 }
319 
setAcquireFence(const std::string & layerName,uint64_t frameNumber,const std::shared_ptr<FenceTime> & acquireFence)320 void TimeStats::setAcquireFence(const std::string& layerName, uint64_t frameNumber,
321                                 const std::shared_ptr<FenceTime>& acquireFence) {
322     if (!mEnabled.load()) return;
323 
324     ATRACE_CALL();
325     ALOGV("[%s]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerName.c_str(), frameNumber,
326           acquireFence->getSignalTime());
327 
328     std::lock_guard<std::mutex> lock(mMutex);
329     if (!timeStatsTracker.count(layerName)) return;
330     LayerRecord& layerRecord = timeStatsTracker[layerName];
331     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
332     if (timeRecord.frameNumber == frameNumber) {
333         timeRecord.acquireFence = acquireFence;
334     }
335 }
336 
setPresentTime(const std::string & layerName,uint64_t frameNumber,nsecs_t presentTime)337 void TimeStats::setPresentTime(const std::string& layerName, uint64_t frameNumber,
338                                nsecs_t presentTime) {
339     if (!mEnabled.load()) return;
340 
341     ATRACE_CALL();
342     ALOGV("[%s]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerName.c_str(), frameNumber,
343           presentTime);
344 
345     std::lock_guard<std::mutex> lock(mMutex);
346     if (!timeStatsTracker.count(layerName)) return;
347     LayerRecord& layerRecord = timeStatsTracker[layerName];
348     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
349     if (timeRecord.frameNumber == frameNumber) {
350         timeRecord.presentTime = presentTime;
351         timeRecord.ready = true;
352         layerRecord.waitData++;
353     }
354 
355     flushAvailableRecordsToStatsLocked(layerName);
356 }
357 
setPresentFence(const std::string & layerName,uint64_t frameNumber,const std::shared_ptr<FenceTime> & presentFence)358 void TimeStats::setPresentFence(const std::string& layerName, uint64_t frameNumber,
359                                 const std::shared_ptr<FenceTime>& presentFence) {
360     if (!mEnabled.load()) return;
361 
362     ATRACE_CALL();
363     ALOGV("[%s]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerName.c_str(), frameNumber,
364           presentFence->getSignalTime());
365 
366     std::lock_guard<std::mutex> lock(mMutex);
367     if (!timeStatsTracker.count(layerName)) return;
368     LayerRecord& layerRecord = timeStatsTracker[layerName];
369     TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
370     if (timeRecord.frameNumber == frameNumber) {
371         timeRecord.presentFence = presentFence;
372         timeRecord.ready = true;
373         layerRecord.waitData++;
374     }
375 
376     flushAvailableRecordsToStatsLocked(layerName);
377 }
378 
onDisconnect(const std::string & layerName)379 void TimeStats::onDisconnect(const std::string& layerName) {
380     if (!mEnabled.load()) return;
381 
382     ATRACE_CALL();
383     ALOGV("[%s]-onDisconnect", layerName.c_str());
384 
385     std::lock_guard<std::mutex> lock(mMutex);
386     if (!timeStatsTracker.count(layerName)) return;
387     flushAvailableRecordsToStatsLocked(layerName);
388     timeStatsTracker.erase(layerName);
389 }
390 
clearLayerRecord(const std::string & layerName)391 void TimeStats::clearLayerRecord(const std::string& layerName) {
392     if (!mEnabled.load()) return;
393 
394     ATRACE_CALL();
395     ALOGV("[%s]-clearLayerRecord", layerName.c_str());
396 
397     std::lock_guard<std::mutex> lock(mMutex);
398     if (!timeStatsTracker.count(layerName)) return;
399     LayerRecord& layerRecord = timeStatsTracker[layerName];
400     layerRecord.timeRecords.clear();
401     layerRecord.prevTimeRecord.ready = false;
402     layerRecord.waitData = -1;
403 }
404 
removeTimeRecord(const std::string & layerName,uint64_t frameNumber)405 void TimeStats::removeTimeRecord(const std::string& layerName, uint64_t frameNumber) {
406     if (!mEnabled.load()) return;
407 
408     ATRACE_CALL();
409     ALOGV("[%s]-[%" PRIu64 "]-removeTimeRecord", layerName.c_str(), frameNumber);
410 
411     std::lock_guard<std::mutex> lock(mMutex);
412     if (!timeStatsTracker.count(layerName)) return;
413     LayerRecord& layerRecord = timeStatsTracker[layerName];
414     size_t removeAt = 0;
415     for (const TimeRecord& record : layerRecord.timeRecords) {
416         if (record.frameNumber == frameNumber) break;
417         removeAt++;
418     }
419     if (removeAt == layerRecord.timeRecords.size()) return;
420     layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
421     if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
422         --layerRecord.waitData;
423     }
424 }
425 
enable()426 void TimeStats::enable() {
427     if (mEnabled.load()) return;
428 
429     ATRACE_CALL();
430 
431     std::lock_guard<std::mutex> lock(mMutex);
432     ALOGD("Enabled");
433     mEnabled.store(true);
434     timeStats.statsStart = static_cast<int64_t>(std::time(0));
435 }
436 
disable()437 void TimeStats::disable() {
438     if (!mEnabled.load()) return;
439 
440     ATRACE_CALL();
441 
442     std::lock_guard<std::mutex> lock(mMutex);
443     ALOGD("Disabled");
444     mEnabled.store(false);
445     timeStats.statsEnd = static_cast<int64_t>(std::time(0));
446 }
447 
clear()448 void TimeStats::clear() {
449     ATRACE_CALL();
450 
451     std::lock_guard<std::mutex> lock(mMutex);
452     ALOGD("Cleared");
453     timeStats.stats.clear();
454     timeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
455     timeStats.statsEnd = 0;
456     timeStats.totalFrames = 0;
457     timeStats.missedFrames = 0;
458     timeStats.clientCompositionFrames = 0;
459 }
460 
isEnabled()461 bool TimeStats::isEnabled() {
462     return mEnabled.load();
463 }
464 
dump(bool asProto,std::optional<uint32_t> maxLayers,String8 & result)465 void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, String8& result) {
466     ATRACE_CALL();
467 
468     std::lock_guard<std::mutex> lock(mMutex);
469     if (timeStats.statsStart == 0) {
470         return;
471     }
472 
473     timeStats.statsEnd = static_cast<int64_t>(std::time(0));
474 
475     if (asProto) {
476         ALOGD("Dumping TimeStats as proto");
477         SFTimeStatsGlobalProto timeStatsProto = timeStats.toProto(maxLayers);
478         result.append(timeStatsProto.SerializeAsString().c_str(), timeStatsProto.ByteSize());
479     } else {
480         ALOGD("Dumping TimeStats as text");
481         result.append(timeStats.toString(maxLayers).c_str());
482         result.append("\n");
483     }
484 }
485 
486 } // namespace android
487