SurfaceFlinger TimeStats Metrics
Add timestats metrics for SurfaceFlinger. Keep track of global metrics
like total frames, missed frames, frames fellback to client
compositions, etc, as well as layer timing metrics like the delta
combination of postTime, desiredPresentTime, acqureTime, latchTime,
presentTime, etc. This metric is aimed at GMScore.
Test: dumpsys SurfaceFlinger --timestats [go/sf-timestats for more args]
Bug: b/70388650
Change-Id: I6e4545aef62f7893020533a4e7521541ea453ecd
Merged-In: I6e4545aef62f7893020533a4e7521541ea453ecd
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
new file mode 100644
index 0000000..5f2dd32
--- /dev/null
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -0,0 +1,498 @@
+/*
+ * 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(bool propagateBackpressure) {
+ if (!mEnabled.load()) return;
+
+ ATRACE_CALL();
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (propagateBackpressure) {
+ timeStats.totalFrames--;
+ }
+ 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::vector<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];
+ // TODO(zzyiwei): change timeRecords to use std::deque
+ timeRecords.erase(timeRecords.begin());
+ 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