SF Timestats: add new metrics
Add the new metrics below:
1) dropped buffers per layer
2) post to acquire histogram
Stop tracking the start and end time for each layer since that doesn't
give any meaningful information. The total/dropped frame per layer is
good enough for now.
Test: dumpsys SurfaceFlinger --timestats <see go/sf-timestats for args>
Bug: b/110954467
Change-Id: I1c8a3a6cc76b7ec4a2e9ab86d9237af95fe9d1e1
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index d7a2886..d77a324 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -178,10 +178,17 @@
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++;
+ timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
+ layerRecord.droppedFrames = 0;
+
+ const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
+ timeRecords[0].frameTime.acquireTime);
+ ALOGV("[%s]-[%" PRIu64 "]-post2acquire[%d]", layerName.c_str(),
+ timeRecords[0].frameTime.frameNumber, postToAcquireMs);
+ timeStatsLayer.deltas["post2acquire"].insert(postToAcquireMs);
const int32_t postToPresentMs = msBetween(timeRecords[0].frameTime.postTime,
timeRecords[0].frameTime.presentTime);
@@ -212,8 +219,6 @@
ALOGV("[%s]-[%" PRIu64 "]-present2present[%d]", layerName.c_str(),
timeRecords[0].frameTime.frameNumber, presentToPresentMs);
timeStatsLayer.deltas["present2present"].insert(presentToPresentMs);
-
- timeStats.stats[layerName].statsEnd = static_cast<int64_t>(std::time(0));
}
prevTimeRecord = timeRecords[0];
timeRecords.pop_front();
@@ -403,6 +408,7 @@
layerRecord.timeRecords.clear();
layerRecord.prevTimeRecord.ready = false;
layerRecord.waitData = -1;
+ layerRecord.droppedFrames = 0;
}
void TimeStats::removeTimeRecord(const std::string& layerName, uint64_t frameNumber) {
@@ -422,8 +428,9 @@
if (removeAt == layerRecord.timeRecords.size()) return;
layerRecord.timeRecords.erase(layerRecord.timeRecords.begin() + removeAt);
if (layerRecord.waitData > static_cast<int32_t>(removeAt)) {
- --layerRecord.waitData;
+ layerRecord.waitData--;
}
+ layerRecord.droppedFrames++;
}
void TimeStats::enable() {
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index 0b1f82e..5ab3934 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -61,6 +61,7 @@
// specific frame are still not fully received. This is not waiting for
// fences to signal, but rather waiting to receive those fences/timestamps.
int32_t waitData = -1;
+ uint32_t droppedFrames = 0;
TimeRecord prevTimeRecord;
std::deque<TimeRecord> timeRecords;
};
@@ -81,8 +82,11 @@
void setPresentTime(const std::string& layerName, uint64_t frameNumber, nsecs_t presentTime);
void setPresentFence(const std::string& layerName, uint64_t frameNumber,
const std::shared_ptr<FenceTime>& presentFence);
+ // On producer disconnect with BufferQueue.
void onDisconnect(const std::string& layerName);
+ // When SF is cleaning up the queue, clear the LayerRecord as well.
void clearLayerRecord(const std::string& layerName);
+ // If SF skips or rejects a buffer, remove the corresponding TimeRecord.
void removeTimeRecord(const std::string& layerName, uint64_t frameNumber);
private:
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
index 21f3ef3..b7b2778 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -68,12 +68,11 @@
}
std::string TimeStatsHelper::TimeStatsLayer::toString() const {
- std::string result = "";
+ std::string result = "\n";
StringAppendF(&result, "layerName = %s\n", layerName.c_str());
StringAppendF(&result, "packageName = %s\n", packageName.c_str());
- StringAppendF(&result, "statsStart = %lld\n", static_cast<long long int>(statsStart));
- StringAppendF(&result, "statsEnd = %lld\n", static_cast<long long int>(statsEnd));
- StringAppendF(&result, "totalFrames= %d\n", totalFrames);
+ StringAppendF(&result, "totalFrames = %d\n", totalFrames);
+ StringAppendF(&result, "droppedFrames = %d\n", droppedFrames);
auto iter = deltas.find("present2present");
if (iter != deltas.end()) {
StringAppendF(&result, "averageFPS = %.3f\n", 1000.0 / iter->second.averageTime());
@@ -90,10 +89,9 @@
std::string result = "SurfaceFlinger TimeStats:\n";
StringAppendF(&result, "statsStart = %lld\n", static_cast<long long int>(statsStart));
StringAppendF(&result, "statsEnd = %lld\n", static_cast<long long int>(statsEnd));
- StringAppendF(&result, "totalFrames= %d\n", totalFrames);
- StringAppendF(&result, "missedFrames= %d\n", missedFrames);
- StringAppendF(&result, "clientCompositionFrames= %d\n", clientCompositionFrames);
- StringAppendF(&result, "TimeStats for each layer is as below:\n");
+ StringAppendF(&result, "totalFrames = %d\n", totalFrames);
+ StringAppendF(&result, "missedFrames = %d\n", missedFrames);
+ StringAppendF(&result, "clientCompositionFrames = %d\n", clientCompositionFrames);
const auto dumpStats = generateDumpStats(maxLayers);
for (auto& ele : dumpStats) {
StringAppendF(&result, "%s", ele->toString().c_str());
@@ -106,15 +104,14 @@
SFTimeStatsLayerProto layerProto;
layerProto.set_layer_name(layerName);
layerProto.set_package_name(packageName);
- layerProto.set_stats_start(statsStart);
- layerProto.set_stats_end(statsEnd);
layerProto.set_total_frames(totalFrames);
+ layerProto.set_dropped_frames(droppedFrames);
for (auto& ele : deltas) {
SFTimeStatsDeltaProto* deltaProto = layerProto.add_deltas();
deltaProto->set_delta_name(ele.first);
for (auto& histEle : ele.second.hist) {
SFTimeStatsHistogramBucketProto* histProto = deltaProto->add_histograms();
- histProto->set_render_millis(histEle.first);
+ histProto->set_time_millis(histEle.first);
histProto->set_frame_count(histEle.second);
}
}
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
index 1798555..99c891b 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -42,9 +42,8 @@
public:
std::string layerName;
std::string packageName;
- int64_t statsStart = 0;
- int64_t statsEnd = 0;
int32_t totalFrames = 0;
+ int32_t droppedFrames = 0;
std::unordered_map<std::string, Histogram> deltas;
std::string toString() const;
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto b/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
index f29fbd1..ab7527e 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
+++ b/services/surfaceflinger/TimeStats/timestatsproto/timestats.proto
@@ -20,46 +20,59 @@
option optimize_for = LITE_RUNTIME;
+// //depot/google3/java/com/google/android/apps/graphics/proto/timestats.proto
+// is based on this proto. Please only make valid protobuf changes to these
+// messages, and keep the other file in sync per Android release. Please also
+// do not include "option optimize_for = LITE_RUNTIME;" on google3 side.
+
+// Next tag: 7
message SFTimeStatsGlobalProto {
- // The start & end timestamps in UTC as
- // milliseconds since January 1, 1970
+ // The stats start time in UTC as seconds since January 1, 1970
optional int64 stats_start = 1;
+ // The stats end time in UTC as seconds since January 1, 1970
optional int64 stats_end = 2;
- // Total frames
+ // Total number of frames presented during tracing period.
optional int32 total_frames = 3;
// Total missed frames of SurfaceFlinger.
optional int32 missed_frames = 4;
// Total frames fallback to client composition.
optional int32 client_composition_frames = 5;
-
+ // Stats per layer. Apps could have multiple layers.
repeated SFTimeStatsLayerProto stats = 6;
}
+// Next tag: 8
message SFTimeStatsLayerProto {
- // The layer name
+ // The name of the visible view layer.
optional string layer_name = 1;
- // The package name
+ // The package name of the application owning this layer.
optional string package_name = 2;
- // The start & end timestamps in UTC as
- // milliseconds since January 1, 1970
+ // The stats start time in UTC as seconds since January 1, 1970
optional int64 stats_start = 3;
+ // The stats end time in UTC as seconds since January 1, 1970
optional int64 stats_end = 4;
- // Distinct frame count.
+ // Total number of frames presented during tracing period.
optional int32 total_frames = 5;
-
+ // Total number of frames dropped by SurfaceFlinger.
+ optional int32 dropped_frames = 7;
+ // There are multiple timestamps tracked in SurfaceFlinger, and these are the
+ // histograms of deltas between different combinations of those timestamps.
repeated SFTimeStatsDeltaProto deltas = 6;
}
+// Next tag: 3
message SFTimeStatsDeltaProto {
// Name of the time interval
optional string delta_name = 1;
- // Histogram of the delta time
+ // Histogram of the delta time. There should be at most 85 buckets ranging
+ // from [0ms, 1ms) to [1000ms, infinity)
repeated SFTimeStatsHistogramBucketProto histograms = 2;
}
+// Next tag: 3
message SFTimeStatsHistogramBucketProto {
- // Lower bound of render time in milliseconds.
- optional int32 render_millis = 1;
+ // Lower bound of time interval in milliseconds.
+ optional int32 time_millis = 1;
// Number of frames in the bucket.
optional int32 frame_count = 2;
}