[TimeStats] Track RenderEngine time per frame.
Bug: 144037240
Test: dumpsys SurfaceFlinger --timestats -dump
Change-Id: I7a4dd680ed08e3a7a05e3fd08d5e133e9d394193
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 626efb8..1895777 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -129,6 +129,29 @@
}
}
+void TimeStats::recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) {
+ if (!mEnabled.load()) return;
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
+ ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
+ mGlobalRecord.renderEngineDurations.pop_front();
+ }
+ mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
+}
+
+void TimeStats::recordRenderEngineDuration(nsecs_t startTime,
+ const std::shared_ptr<FenceTime>& endTime) {
+ if (!mEnabled.load()) return;
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (mGlobalRecord.renderEngineDurations.size() == MAX_NUM_TIME_RECORDS) {
+ ALOGE("RenderEngineTimes are already at its maximum size[%zu]", MAX_NUM_TIME_RECORDS);
+ mGlobalRecord.renderEngineDurations.pop_front();
+ }
+ mGlobalRecord.renderEngineDurations.push_back({startTime, endTime});
+}
+
bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) {
if (!timeRecord->ready) {
ALOGV("[%d]-[%" PRIu64 "]-presentFence is still not received", layerId,
@@ -501,6 +524,31 @@
mGlobalRecord.prevPresentTime = curPresentTime;
mGlobalRecord.presentFences.pop_front();
}
+ while (!mGlobalRecord.renderEngineDurations.empty()) {
+ const auto duration = mGlobalRecord.renderEngineDurations.front();
+ const auto& endTime = duration.endTime;
+
+ nsecs_t endNs = -1;
+
+ if (auto val = std::get_if<nsecs_t>(&endTime)) {
+ endNs = *val;
+ } else {
+ endNs = std::get<std::shared_ptr<FenceTime>>(endTime)->getSignalTime();
+ }
+
+ if (endNs == Fence::SIGNAL_TIME_PENDING) break;
+
+ if (endNs < 0) {
+ ALOGE("RenderEngineTiming is invalid!");
+ mGlobalRecord.renderEngineDurations.pop_front();
+ continue;
+ }
+
+ const int32_t renderEngineMs = msBetween(duration.startTime, endNs);
+ mTimeStats.renderEngineTiming.insert(renderEngineMs);
+
+ mGlobalRecord.renderEngineDurations.pop_front();
+ }
}
void TimeStats::setPresentFenceGlobal(const std::shared_ptr<FenceTime>& presentFence) {
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index 670bc8e..65e5cf4 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -27,6 +27,7 @@
#include <mutex>
#include <optional>
#include <unordered_map>
+#include <variant>
using namespace android::surfaceflinger;
@@ -50,6 +51,13 @@
// 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;
+ // Records the start time and end times for when RenderEngine begins work.
+ // The start time corresponds to the beginning of RenderEngine::drawLayers.
+ // The end time corresponds to when RenderEngine finishes rendering.
+ virtual void recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) = 0;
+ // Same as above, but passes in a fence representing the end time.
+ virtual void recordRenderEngineDuration(nsecs_t startTime,
+ const std::shared_ptr<FenceTime>& readyFence) = 0;
virtual void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
nsecs_t postTime) = 0;
@@ -58,6 +66,8 @@
virtual void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) = 0;
virtual void setAcquireFence(int32_t layerId, uint64_t frameNumber,
const std::shared_ptr<FenceTime>& acquireFence) = 0;
+ // SetPresent{Time, Fence} are not expected to be called in the critical
+ // rendering path, as they flush prior fences if those fences have fired.
virtual void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) = 0;
virtual void setPresentFence(int32_t layerId, uint64_t frameNumber,
const std::shared_ptr<FenceTime>& presentFence) = 0;
@@ -107,9 +117,15 @@
nsecs_t prevTime = 0;
};
+ struct RenderEngineDuration {
+ nsecs_t startTime;
+ std::variant<nsecs_t, std::shared_ptr<FenceTime>> endTime;
+ };
+
struct GlobalRecord {
nsecs_t prevPresentTime = 0;
std::deque<std::shared_ptr<FenceTime>> presentFences;
+ std::deque<RenderEngineDuration> renderEngineDurations;
};
public:
@@ -124,6 +140,9 @@
void incrementClientCompositionFrames() override;
void recordFrameDuration(nsecs_t startTime, nsecs_t endTime) override;
+ void recordRenderEngineDuration(nsecs_t startTime, nsecs_t endTime) override;
+ void recordRenderEngineDuration(nsecs_t startTime,
+ const std::shared_ptr<FenceTime>& readyFence) override;
void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName,
nsecs_t postTime) override;
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
index 83cd45a..7e43880 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -113,6 +113,8 @@
result.append(presentToPresent.toString());
StringAppendF(&result, "frameDuration histogram is as below:\n");
result.append(frameDuration.toString());
+ StringAppendF(&result, "renderEngineTiming histogram is as below:\n");
+ result.append(renderEngineTiming.toString());
const auto dumpStats = generateDumpStats(maxLayers);
for (const auto& ele : dumpStats) {
result.append(ele->toString());
@@ -165,6 +167,11 @@
histProto->set_time_millis(histEle.first);
histProto->set_frame_count(histEle.second);
}
+ for (const auto& histEle : renderEngineTiming.hist) {
+ SFTimeStatsHistogramBucketProto* histProto = globalProto.add_render_engine_timing();
+ 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 6b28970..bd97ecc 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -62,6 +62,7 @@
int64_t displayOnTime = 0;
Histogram presentToPresent;
Histogram frameDuration;
+ Histogram renderEngineTiming;
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 96430b3..5fd4a39 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: 11
+// Next tag: 12
message SFTimeStatsGlobalProto {
// The stats start time in UTC as seconds since January 1, 1970
optional int64 stats_start = 1;
@@ -45,6 +45,8 @@
repeated SFTimeStatsHistogramBucketProto present_to_present = 8;
// Frame CPU duration histogram.
repeated SFTimeStatsHistogramBucketProto frame_duration = 10;
+ // Frame GPU duration histogram.
+ repeated SFTimeStatsHistogramBucketProto render_engine_timing = 11;
// Stats per layer. Apps could have multiple layers.
repeated SFTimeStatsLayerProto stats = 6;
}