services/surfaceflinger/TimeStats/TimeStats.cpp

/*
 * Copyright 2018 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
#undef LOG_TAG
#define LOG_TAG "TimeStats"
#define ATRACE_TAG ATRACE_TAG_GRAPHICS

#include "TimeStats.h"

#include <android-base/stringprintf.h>

#include <log/log.h>

#include <utils/String8.h>
#include <utils/Trace.h>

#include <algorithm>
#include <regex>

namespace android {

TimeStats& TimeStats::getInstance() {
    static std::unique_ptr<TimeStats> sInstance;
    static std::once_flag sOnceFlag;

    std::call_once(sOnceFlag, [] { sInstance.reset(new TimeStats); });
    return *sInstance.get();
}

void TimeStats::parseArgs(bool asProto, const Vector<String16>& args, size_t& index,
                          String8& result) {
    ATRACE_CALL();

    if (args.size() > index + 10) {
        ALOGD("Invalid args count");
        return;
    }

    std::unordered_map<std::string, int32_t> argsMap;
    while (index < args.size()) {
        argsMap[std::string(String8(args[index]).c_str())] = index;
        ++index;
    }

    if (argsMap.count("-disable")) {
        disable();
    }

    if (argsMap.count("-dump")) {
        int64_t maxLayers = 0;
        auto iter = argsMap.find("-maxlayers");
        if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
            maxLayers = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
            maxLayers = std::clamp(maxLayers, int64_t(0), int64_t(UINT32_MAX));
        }

        dump(asProto, static_cast<uint32_t>(maxLayers), result);
    }

    if (argsMap.count("-clear")) {
        clear();
    }

    if (argsMap.count("-enable")) {
        enable();
    }
}

void TimeStats::incrementTotalFrames() {
    if (!mEnabled.load()) return;

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    timeStats.totalFrames++;
}

void TimeStats::incrementMissedFrames() {
    if (!mEnabled.load()) return;

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    timeStats.missedFrames++;
}

void TimeStats::incrementClientCompositionFrames() {
    if (!mEnabled.load()) return;

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    timeStats.clientCompositionFrames++;
}

bool TimeStats::recordReadyLocked(const std::string& layerName, TimeRecord* timeRecord) {
    if (!timeRecord->ready) {
        ALOGV("[%s]-[%" PRIu64 "]-presentFence is still not received", layerName.c_str(),
              timeRecord->frameNumber);
        return false;
    }

    if (timeRecord->acquireFence != nullptr) {
        if (timeRecord->acquireFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
            return false;
        }
        if (timeRecord->acquireFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
            timeRecord->acquireTime = timeRecord->acquireFence->getSignalTime();
            timeRecord->acquireFence = nullptr;
        } else {
            ALOGV("[%s]-[%" PRIu64 "]-acquireFence signal time is invalid", layerName.c_str(),
                  timeRecord->frameNumber);
        }
    }

    if (timeRecord->presentFence != nullptr) {
        if (timeRecord->presentFence->getSignalTime() == Fence::SIGNAL_TIME_PENDING) {
            return false;
        }
        if (timeRecord->presentFence->getSignalTime() != Fence::SIGNAL_TIME_INVALID) {
            timeRecord->presentTime = timeRecord->presentFence->getSignalTime();
            timeRecord->presentFence = nullptr;
        } else {
            ALOGV("[%s]-[%" PRIu64 "]-presentFence signal time invalid", layerName.c_str(),
                  timeRecord->frameNumber);
        }
    }

    return true;
}

static int32_t msBetween(nsecs_t start, nsecs_t end) {
    int64_t delta = (end - start) / 1000000;
    delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
    return static_cast<int32_t>(delta);
}

void TimeStats::flushAvailableRecordsToStatsLocked(const std::string& layerName) {
    ATRACE_CALL();

    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord;
    std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords;
    while (!timeRecords.empty()) {
        if (!recordReadyLocked(layerName, &timeRecords[0])) break;
        ALOGV("[%s]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerName.c_str(),
              timeRecords[0].frameNumber, timeRecords[0].presentTime);

        if (prevTimeRecord.ready) {
            if (!timeStats.stats.count(layerName)) {
                timeStats.stats[layerName].layerName = layerName;
                timeStats.stats[layerName].statsStart = static_cast<int64_t>(std::time(0));
            }
            TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timeStats.stats[layerName];
            timeStatsLayer.totalFrames++;

            const int32_t postToPresentMs =
                    msBetween(timeRecords[0].postTime, timeRecords[0].presentTime);
            ALOGV("[%s]-[%" PRIu64 "]-post2present[%d]", layerName.c_str(),
                  timeRecords[0].frameNumber, postToPresentMs);
            timeStatsLayer.deltas["post2present"].insert(postToPresentMs);

            const int32_t acquireToPresentMs =
                    msBetween(timeRecords[0].acquireTime, timeRecords[0].presentTime);
            ALOGV("[%s]-[%" PRIu64 "]-acquire2present[%d]", layerName.c_str(),
                  timeRecords[0].frameNumber, acquireToPresentMs);
            timeStatsLayer.deltas["acquire2present"].insert(acquireToPresentMs);

            const int32_t latchToPresentMs =
                    msBetween(timeRecords[0].latchTime, timeRecords[0].presentTime);
            ALOGV("[%s]-[%" PRIu64 "]-latch2present[%d]", layerName.c_str(),
                  timeRecords[0].frameNumber, latchToPresentMs);
            timeStatsLayer.deltas["latch2present"].insert(latchToPresentMs);

            const int32_t desiredToPresentMs =
                    msBetween(timeRecords[0].desiredTime, timeRecords[0].presentTime);
            ALOGV("[%s]-[%" PRIu64 "]-desired2present[%d]", layerName.c_str(),
                  timeRecords[0].frameNumber, desiredToPresentMs);
            timeStatsLayer.deltas["desired2present"].insert(desiredToPresentMs);

            const int32_t presentToPresentMs =
                    msBetween(prevTimeRecord.presentTime, timeRecords[0].presentTime);
            ALOGV("[%s]-[%" PRIu64 "]-present2present[%d]", layerName.c_str(),
                  timeRecords[0].frameNumber, presentToPresentMs);
            timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);

            timeStats.stats[layerName].statsEnd = static_cast<int64_t>(std::time(0));
        }
        prevTimeRecord = timeRecords[0];
        timeRecords.pop_front();
        layerRecord.waitData--;
    }
}

static bool layerNameIsValid(const std::string& layerName) {
    // This regular expression captures the following layer names for instance:
    // 1) StatusBat#0
    // 2) NavigationBar#1
    // 3) com.*#0
    // 4) SurfaceView - com.*#0
    // Using [-\\s\t]+ for the conjunction part between SurfaceView and com.* is
    // a bit more robust in case there's a slight change.
    // The layer name would only consist of . / $ _ 0-9 a-z A-Z in most cases.
    std::regex re("(((SurfaceView[-\\s\\t]+)?com\\.[./$\\w]+)|((Status|Navigation)Bar))#\\d+");
    return std::regex_match(layerName.begin(), layerName.end(), re);
}

void TimeStats::setPostTime(const std::string& layerName, uint64_t frameNumber, nsecs_t postTime) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-PostTime[%" PRId64 "]", layerName.c_str(), frameNumber, postTime);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName) && !layerNameIsValid(layerName)) {
        return;
    }
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    if (layerRecord.timeRecords.size() == MAX_NUM_TIME_RECORDS) {
        ALOGV("[%s]-timeRecords is already at its maximum size[%zu]", layerName.c_str(),
              MAX_NUM_TIME_RECORDS);
        // TODO(zzyiwei): if this happens, there must be a present fence missing
        // or waitData is not in the correct position. Need to think out a
        // reasonable way to recover from this state.
        return;
    }
    // For most media content, the acquireFence is invalid because the buffer is
    // ready at the queueBuffer stage. In this case, acquireTime should be given
    // a default value as postTime.
    TimeRecord timeRecord = {
            .frameNumber = frameNumber,
            .postTime = postTime,
            .acquireTime = postTime,
    };
    layerRecord.timeRecords.push_back(timeRecord);
    if (layerRecord.waitData < 0 ||
        layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
        layerRecord.waitData = layerRecord.timeRecords.size() - 1;
}

void TimeStats::setLatchTime(const std::string& layerName, uint64_t frameNumber,
                             nsecs_t latchTime) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-LatchTime[%" PRId64 "]", layerName.c_str(), frameNumber, latchTime);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.latchTime = latchTime;
    }
}

void TimeStats::setDesiredTime(const std::string& layerName, uint64_t frameNumber,
                               nsecs_t desiredTime) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-DesiredTime[%" PRId64 "]", layerName.c_str(), frameNumber,
          desiredTime);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.desiredTime = desiredTime;
    }
}

void TimeStats::setAcquireTime(const std::string& layerName, uint64_t frameNumber,
                               nsecs_t acquireTime) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-AcquireTime[%" PRId64 "]", layerName.c_str(), frameNumber,
          acquireTime);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.acquireTime = acquireTime;
    }
}

void TimeStats::setAcquireFence(const std::string& layerName, uint64_t frameNumber,
                                const std::shared_ptr<FenceTime>& acquireFence) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-AcquireFenceTime[%" PRId64 "]", layerName.c_str(), frameNumber,
          acquireFence->getSignalTime());

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.acquireFence = acquireFence;
    }
}

void TimeStats::setPresentTime(const std::string& layerName, uint64_t frameNumber,
                               nsecs_t presentTime) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-PresentTime[%" PRId64 "]", layerName.c_str(), frameNumber,
          presentTime);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.presentTime = presentTime;
        timeRecord.ready = true;
        layerRecord.waitData++;
    }

    flushAvailableRecordsToStatsLocked(layerName);
}

void TimeStats::setPresentFence(const std::string& layerName, uint64_t frameNumber,
                                const std::shared_ptr<FenceTime>& presentFence) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-PresentFenceTime[%" PRId64 "]", layerName.c_str(), frameNumber,
          presentFence->getSignalTime());

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    TimeRecord& timeRecord = layerRecord.timeRecords[layerRecord.waitData];
    if (timeRecord.frameNumber == frameNumber) {
        timeRecord.presentFence = presentFence;
        timeRecord.ready = true;
        layerRecord.waitData++;
    }

    flushAvailableRecordsToStatsLocked(layerName);
}

void TimeStats::onDisconnect(const std::string& layerName) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-onDisconnect", layerName.c_str());

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    flushAvailableRecordsToStatsLocked(layerName);
    timeStatsTracker.erase(layerName);
}

void TimeStats::clearLayerRecord(const std::string& layerName) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-clearLayerRecord", layerName.c_str());

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    layerRecord.timeRecords.clear();
    layerRecord.prevTimeRecord.ready = false;
    layerRecord.waitData = -1;
}

void TimeStats::removeTimeRecord(const std::string& layerName, uint64_t frameNumber) {
    if (!mEnabled.load()) return;

    ATRACE_CALL();
    ALOGV("[%s]-[%" PRIu64 "]-removeTimeRecord", layerName.c_str(), frameNumber);

    std::lock_guard<std::mutex> lock(mMutex);
    if (!timeStatsTracker.count(layerName)) return;
    LayerRecord& layerRecord = timeStatsTracker[layerName];
    size_t removeAt = 0;
    for (const TimeRecord& record : layerRecord.timeRecords) {
        if (record.frameNumber == frameNumber) break;
        removeAt++;
    }
    if (removeAt == layerRecord.timeRecords.size()) return;
    layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
    if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
        --layerRecord.waitData;
    }
}

void TimeStats::enable() {
    if (mEnabled.load()) return;

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    ALOGD("Enabled");
    mEnabled.store(true);
    timeStats.statsStart = static_cast<int64_t>(std::time(0));
}

void TimeStats::disable() {
    if (!mEnabled.load()) return;

    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    ALOGD("Disabled");
    mEnabled.store(false);
    timeStats.statsEnd = static_cast<int64_t>(std::time(0));
}

void TimeStats::clear() {
    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    ALOGD("Cleared");
    timeStats.dumpStats.clear();
    timeStats.stats.clear();
    timeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0);
    timeStats.statsEnd = 0;
    timeStats.totalFrames = 0;
    timeStats.missedFrames = 0;
    timeStats.clientCompositionFrames = 0;
}

bool TimeStats::isEnabled() {
    return mEnabled.load();
}

void TimeStats::dump(bool asProto, uint32_t maxLayers, String8& result) {
    ATRACE_CALL();

    std::lock_guard<std::mutex> lock(mMutex);
    if (timeStats.statsStart == 0) {
        return;
    }

    timeStats.statsEnd = static_cast<int64_t>(std::time(0));

    // TODO(zzyiwei): refactor dumpStats into TimeStatsHelper
    timeStats.dumpStats.clear();
    for (auto& ele : timeStats.stats) {
        timeStats.dumpStats.push_back(&ele.second);
    }

    std::sort(timeStats.dumpStats.begin(), timeStats.dumpStats.end(),
              [](TimeStatsHelper::TimeStatsLayer* const& l,
                 TimeStatsHelper::TimeStatsLayer* const& r) {
                  return l->totalFrames > r->totalFrames;
              });

    if (maxLayers != 0 && maxLayers < timeStats.dumpStats.size()) {
        timeStats.dumpStats.resize(maxLayers);
    }

    if (asProto) {
        dumpAsProtoLocked(result);
    } else {
        dumpAsTextLocked(result);
    }
}

void TimeStats::dumpAsTextLocked(String8& result) {
    ALOGD("Dumping TimeStats as text");
    result.append(timeStats.toString().c_str());
    result.append("\n");
}

void TimeStats::dumpAsProtoLocked(String8& result) {
    ALOGD("Dumping TimeStats as proto");
    SFTimeStatsGlobalProto timeStatsProto = timeStats.toProto();
    result.append(timeStatsProto.SerializeAsString().c_str(), timeStatsProto.ByteSize());
}

} // namespace android