[TimeStats] Track per-frame CPU time.
This measures from the beginning of the invalidate message, until
CompositionEngine::present finishes.
Bug: 144037240
Test: dumpsys SurfaceFlinger --timestats -dump
Change-Id: I1c686db9fa1746518c48810bf385041806ce06d2
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 611afce..626efb8 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -20,14 +20,13 @@
#include "TimeStats.h"
#include <android-base/stringprintf.h>
-
#include <log/log.h>
-
#include <utils/String8.h>
#include <utils/Timers.h>
#include <utils/Trace.h>
#include <algorithm>
+#include <chrono>
namespace android {
@@ -113,6 +112,23 @@
mTimeStats.clientCompositionFrames++;
}
+static int32_t msBetween(nsecs_t start, nsecs_t end) {
+ int64_t delta = std::chrono::duration_cast<std::chrono::milliseconds>(
+ std::chrono::nanoseconds(end - start))
+ .count();
+ delta = std::clamp(delta, int64_t(INT32_MIN), int64_t(INT32_MAX));
+ return static_cast<int32_t>(delta);
+}
+
+void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) {
+ if (!mEnabled.load()) return;
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (mPowerTime.powerMode == HWC_POWER_MODE_NORMAL) {
+ mTimeStats.frameDuration.insert(msBetween(startTime, endTime));
+ }
+}
+
bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
if (!timeRecord->ready) {
ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
@@ -149,12 +165,6 @@
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(int32_t layerId) {
ATRACE_CALL();
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index 6e71f5a..670bc8e 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -44,6 +44,13 @@
virtual void incrementMissedFrames() = 0;
virtual void incrementClientCompositionFrames() = 0;
+ // Records the start and end times for a frame.
+ // The start time is the same as the beginning of a SurfaceFlinger
+ // invalidate message.
+ // The end time corresponds to when SurfaceFlinger finishes submitting the
+ // request to HWC to present a frame.
+ virtual void recordFrameDuration(nsecs_t startTime, nsecs_t endTime) = 0;
+
virtual void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
nsecs_t postTime) = 0;
virtual void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) = 0;
@@ -116,6 +123,8 @@
void incrementMissedFrames() override;
void incrementClientCompositionFrames() override;
+ void recordFrameDuration(nsecs_t startTime, nsecs_t endTime) override;
+
void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
nsecs_t postTime) override;
void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) override;
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
index 16d2da0..83cd45a 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -111,6 +111,8 @@
StringAppendF(&result, "totalP2PTime = %" PRId64 " ms\n", presentToPresent.totalTime());
StringAppendF(&result, "presentToPresent histogram is as below:\n");
result.append(presentToPresent.toString());
+ StringAppendF(&result, "frameDuration histogram is as below:\n");
+ result.append(frameDuration.toString());
const auto dumpStats = generateDumpStats(maxLayers);
for (const auto& ele : dumpStats) {
result.append(ele->toString());
@@ -158,6 +160,11 @@
histProto->set_time_millis(histEle.first);
histProto->set_frame_count(histEle.second);
}
+ for (const auto& histEle : frameDuration.hist) {
+ SFTimeStatsHistogramBucketProto* histProto = globalProto.add_frame_duration();
+ histProto->set_time_millis(histEle.first);
+ histProto->set_frame_count(histEle.second);
+ }
const auto dumpStats = generateDumpStats(maxLayers);
for (const auto& ele : dumpStats) {
SFTimeStatsLayerProto* layerProto = globalProto.add_stats();
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
index f2ac7ff..6b28970 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -61,6 +61,7 @@
int32_t clientCompositionFrames = 0;
int64_t displayOnTime = 0;
Histogram presentToPresent;
+ Histogram frameDuration;
std::unordered_map<std::string, TimeStatsLayer> stats;
std::unordered_map<uint32_t, nsecs_t> refreshRateStats;
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto b/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
index 0dacbeb..96430b3 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
+++ b/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
@@ -25,7 +25,7 @@
// changes to these messages, and keep google3 side proto messages in sync if
// the end to end pipeline needs to be updated.
-// Next tag: 10
+// Next tag: 11
message SFTimeStatsGlobalProto {
// The stats start time in UTC as seconds since January 1, 1970
optional int64 stats_start = 1;
@@ -43,6 +43,8 @@
repeated SFTimeStatsDisplayConfigBucketProto display_config_stats = 9;
// Present to present histogram.
repeated SFTimeStatsHistogramBucketProto present_to_present = 8;
+ // Frame CPU duration histogram.
+ repeated SFTimeStatsHistogramBucketProto frame_duration = 10;
// Stats per layer. Apps could have multiple layers.
repeated SFTimeStatsLayerProto stats = 6;
}