blob: 9c34aa726b30cb1c39350fdf27e00dcdf3c78929 [file] [log] [blame]
/*
* 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")) {
std::optional<uint32_t> maxLayers = std::nullopt;
auto iter = argsMap.find("-maxlayers");
if (iter != argsMap.end() && iter->second + 1 < static_cast<int32_t>(args.size())) {
int64_t value = strtol(String8(args[iter->second + 1]).c_str(), nullptr, 10);
value = std::clamp(value, int64_t(0), int64_t(UINT32_MAX));
maxLayers = static_cast<uint32_t>(value);
}
dump(asProto, 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);
}
static std::string getPackageName(const std::string& layerName) {
// This regular expression captures the following for instance:
// StatusBar in StatusBar#0
// com.appname in com.appname/com.appname.activity#0
// com.appname in SurfaceView - com.appname/com.appname.activity#0
const std::regex re("(?:SurfaceView[-\\s\\t]+)?([^/]+).*#\\d+");
std::smatch match;
if (std::regex_match(layerName.begin(), layerName.end(), match, re)) {
// There must be a match for group 1 otherwise the whole string is not
// matched and the above will return false
return match[1];
}
return "";
}
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].packageName = getPackageName(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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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];
if (layerRecord.waitData < 0 ||
layerRecord.waitData >= static_cast<int32_t>(layerRecord.timeRecords.size()))
return;
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.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, std::optional<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));
if (asProto) {
ALOGD("Dumping TimeStats as proto");
SFTimeStatsGlobalProto timeStatsProto = timeStats.toProto(maxLayers);
result.append(timeStatsProto.SerializeAsString().c_str(), timeStatsProto.ByteSize());
} else {
ALOGD("Dumping TimeStats as text");
result.append(timeStats.toString(maxLayers).c_str());
result.append("\n");
}
}
} // namespace android