[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/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp
index b4d748d..010b52e 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -1601,6 +1601,7 @@
ATRACE_CALL();
switch (what) {
case MessageQueue::INVALIDATE: {
+ const nsecs_t frameStart = systemTime();
// calculate the expected present time once and use the cached
// value throughout this frame to make sure all layers are
// seeing this same value.
@@ -1665,6 +1666,13 @@
// Signal a refresh if a transaction modified the window state,
// a new buffer was latched, or if HWC has requested a full
// repaint
+ if (mFrameStartTime <= 0) {
+ // We should only use the time of the first invalidate
+ // message that signals a refresh as the beginning of the
+ // frame. Otherwise the real frame time will be
+ // underestimated.
+ mFrameStartTime = frameStart;
+ }
signalRefresh();
}
break;
@@ -1748,6 +1756,9 @@
mGeometryInvalid = false;
mCompositionEngine->present(refreshArgs);
+ mTimeStats->recordFrameDuration(mFrameStartTime, systemTime());
+ // Reset the frame start time now that we've recorded this frame.
+ mFrameStartTime = 0;
postFrame();
postComposition();
diff --git a/services/surfaceflinger/SurfaceFlinger.h b/services/surfaceflinger/SurfaceFlinger.h
index 50b3ae4..5958109 100644
--- a/services/surfaceflinger/SurfaceFlinger.h
+++ b/services/surfaceflinger/SurfaceFlinger.h
@@ -1148,6 +1148,9 @@
bool mPendingSyncInputWindows GUARDED_BY(mStateLock);
Hwc2::impl::PowerAdvisor mPowerAdvisor;
+ // This should only be accessed on the main thread.
+ nsecs_t mFrameStartTime = 0;
+
std::unique_ptr<RefreshRateOverlay> mRefreshRateOverlay;
// Flag used to set override allowed display configs from backdoor
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;
}
diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
index 7b60fa2..069344a 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -20,11 +20,11 @@
#include <TimeStats/TimeStats.h>
#include <gmock/gmock.h>
#include <gtest/gtest.h>
-
#include <log/log.h>
#include <utils/String16.h>
#include <utils/Vector.h>
+#include <chrono>
#include <random>
#include <unordered_set>
@@ -278,6 +278,31 @@
EXPECT_EQ(2, histogramProto.time_millis());
}
+TEST_F(TimeStatsTest, canInsertGlobalFrameDuration) {
+ EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
+
+ using namespace std::chrono_literals;
+
+ mTimeStats->setPowerMode(HWC_POWER_MODE_OFF);
+ mTimeStats
+ ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(),
+ std::chrono::duration_cast<std::chrono::nanoseconds>(5ms)
+ .count());
+ mTimeStats->setPowerMode(HWC_POWER_MODE_NORMAL);
+ mTimeStats
+ ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(3ms).count(),
+ std::chrono::duration_cast<std::chrono::nanoseconds>(6ms)
+ .count());
+
+ SFTimeStatsGlobalProto globalProto;
+ ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO)));
+
+ ASSERT_EQ(1, globalProto.frame_duration_size());
+ const SFTimeStatsHistogramBucketProto& histogramProto = globalProto.frame_duration().Get(0);
+ EXPECT_EQ(1, histogramProto.frame_count());
+ EXPECT_EQ(3, histogramProto.time_millis());
+}
+
TEST_F(TimeStatsTest, canInsertOneLayerTimeStats) {
EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
diff --git a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
index b1634a8..e94af49 100644
--- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
+++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
@@ -34,6 +34,7 @@
MOCK_METHOD0(incrementTotalFrames, void());
MOCK_METHOD0(incrementMissedFrames, void());
MOCK_METHOD0(incrementClientCompositionFrames, void());
+ MOCK_METHOD2(recordFrameDuration, void(nsecs_t, nsecs_t));
MOCK_METHOD4(setPostTime, void(int32_t, uint64_t, const std::string&, nsecs_t));
MOCK_METHOD3(setLatchTime, void(int32_t, uint64_t, nsecs_t));
MOCK_METHOD3(setDesiredTime, void(int32_t, uint64_t, nsecs_t));