Home | History | Annotate | Download | only in TimeStats 
      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 
     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 
     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 
     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 
     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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    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 
    461 bool TimeStats::isEnabled() {
    462     return mEnabled.load();
    463 }
    464 
    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