[TimeStats] Expose pathological latch counters
* Missed latch because the acquire fence didn't fire
* Latched early because the desired present time was bad
Bug: 135478131
Test: libsurfaceflinger_unittest
Change-Id: Id02a62c222cb497c05889dd198be5fea6d64893a
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp
index 12c98da..bed2471 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.cpp
+++ b/services/surfaceflinger/TimeStats/TimeStats.cpp
@@ -352,7 +352,12 @@
TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName];
timeStatsLayer.totalFrames++;
timeStatsLayer.droppedFrames += layerRecord.droppedFrames;
+ timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames;
+ timeStatsLayer.badDesiredPresentFrames += layerRecord.badDesiredPresentFrames;
+
layerRecord.droppedFrames = 0;
+ layerRecord.lateAcquireFrames = 0;
+ layerRecord.badDesiredPresentFrames = 0;
const int32_t postToAcquireMs = msBetween(timeRecords[0].frameTime.postTime,
timeRecords[0].frameTime.acquireTime);
@@ -466,6 +471,36 @@
}
}
+void TimeStats::incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) {
+ if (!mEnabled.load()) return;
+
+ ATRACE_CALL();
+ ALOGV("[%d]-LatchSkipped-Reason[%d]", layerId,
+ static_cast<std::underlying_type<LatchSkipReason>::type>(reason));
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (!mTimeStatsTracker.count(layerId)) return;
+ LayerRecord& layerRecord = mTimeStatsTracker[layerId];
+
+ switch (reason) {
+ case LatchSkipReason::LateAcquire:
+ layerRecord.lateAcquireFrames++;
+ break;
+ }
+}
+
+void TimeStats::incrementBadDesiredPresent(int32_t layerId) {
+ if (!mEnabled.load()) return;
+
+ ATRACE_CALL();
+ ALOGV("[%d]-BadDesiredPresent", layerId);
+
+ std::lock_guard<std::mutex> lock(mMutex);
+ if (!mTimeStatsTracker.count(layerId)) return;
+ LayerRecord& layerRecord = mTimeStatsTracker[layerId];
+ layerRecord.badDesiredPresentFrames++;
+}
+
void TimeStats::setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) {
if (!mEnabled.load()) return;
diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h
index 71f06af..a2843c8 100644
--- a/services/surfaceflinger/TimeStats/TimeStats.h
+++ b/services/surfaceflinger/TimeStats/TimeStats.h
@@ -70,6 +70,18 @@
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;
+ // Reasons why latching a particular buffer may be skipped
+ enum class LatchSkipReason {
+ // If the acquire fence did not fire on some devices we skip latching
+ // the buffer until the fence fires.
+ LateAcquire,
+ };
+ // Increments the counter of skipped latch buffers.
+ virtual void incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) = 0;
+ // Increments the counter of bad desired present times for this layer.
+ // Bad desired present times are "implausible" and cause SurfaceFlinger to
+ // latch a buffer immediately to avoid stalling.
+ virtual void incrementBadDesiredPresent(int32_t layerId) = 0;
virtual void setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) = 0;
virtual void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) = 0;
virtual void setAcquireFence(int32_t layerId, uint64_t frameNumber,
@@ -116,6 +128,8 @@
// fences to signal, but rather waiting to receive those fences/timestamps.
int32_t waitData = -1;
uint32_t droppedFrames = 0;
+ uint32_t lateAcquireFrames = 0;
+ uint32_t badDesiredPresentFrames = 0;
TimeRecord prevTimeRecord;
std::deque<TimeRecord> timeRecords;
};
@@ -200,6 +214,8 @@
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;
+ void incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) override;
+ void incrementBadDesiredPresent(int32_t layerId) override;
void setDesiredTime(int32_t layerId, uint64_t frameNumber, nsecs_t desiredTime) override;
void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) override;
void setAcquireFence(int32_t layerId, uint64_t frameNumber,
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
index 0ba90e2..1c910aa 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -83,6 +83,8 @@
StringAppendF(&result, "packageName = %s\n", packageName.c_str());
StringAppendF(&result, "totalFrames = %d\n", totalFrames);
StringAppendF(&result, "droppedFrames = %d\n", droppedFrames);
+ StringAppendF(&result, "lateAcquireFrames = %d\n", lateAcquireFrames);
+ StringAppendF(&result, "badDesiredPresentFrames = %d\n", badDesiredPresentFrames);
const auto iter = deltas.find("present2present");
if (iter != deltas.end()) {
StringAppendF(&result, "averageFPS = %.3f\n", 1000.0 / iter->second.averageTime());
diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
index 702c50e..e374b73 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -46,6 +46,8 @@
std::string packageName;
int32_t totalFrames = 0;
int32_t droppedFrames = 0;
+ int32_t lateAcquireFrames = 0;
+ int32_t badDesiredPresentFrames = 0;
std::unordered_map<std::string, Histogram> deltas;
std::string toString() const;