[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/BufferQueueLayer.cpp b/services/surfaceflinger/BufferQueueLayer.cpp
index b55e62b..bd8eafe 100644
--- a/services/surfaceflinger/BufferQueueLayer.cpp
+++ b/services/surfaceflinger/BufferQueueLayer.cpp
@@ -117,6 +117,10 @@
"relative to expectedPresent %" PRId64,
getDebugName(), addedTime, expectedPresentTime);
+ if (!isPlausible) {
+ mFlinger->mTimeStats->incrementBadDesiredPresent(getSequence());
+ }
+
const bool isDue = addedTime < expectedPresentTime;
return isDue || !isPlausible;
}
@@ -154,7 +158,14 @@
// able to be latched. To avoid this, grab this buffer anyway.
return true;
}
- return mQueueItems[0].mFenceTime->getSignalTime() != Fence::SIGNAL_TIME_PENDING;
+ const bool fenceSignaled =
+ mQueueItems[0].mFenceTime->getSignalTime() != Fence::SIGNAL_TIME_PENDING;
+ if (!fenceSignaled) {
+ mFlinger->mTimeStats->incrementLatchSkipped(getSequence(),
+ TimeStats::LatchSkipReason::LateAcquire);
+ }
+
+ return fenceSignaled;
}
bool BufferQueueLayer::framePresentTimeIsCurrent(nsecs_t expectedPresentTime) const {
diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp
index 287fe89..b465a91 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -401,7 +401,14 @@
return true;
}
- return getDrawingState().acquireFence->getStatus() == Fence::Status::Signaled;
+ const bool fenceSignaled =
+ getDrawingState().acquireFence->getStatus() == Fence::Status::Signaled;
+ if (!fenceSignaled) {
+ mFlinger->mTimeStats->incrementLatchSkipped(getSequence(),
+ TimeStats::LatchSkipReason::LateAcquire);
+ }
+
+ return fenceSignaled;
}
bool BufferStateLayer::framePresentTimeIsCurrent(nsecs_t expectedPresentTime) const {
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;
diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
index 68e6697..a170e34 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -306,6 +306,41 @@
EXPECT_EQ(CLIENT_COMPOSITION_FRAMES, globalProto.client_composition_frames());
}
+TEST_F(TimeStatsTest, canIncreaseLateAcquireFrames) {
+ // this stat is not in the proto so verify by checking the string dump
+ constexpr size_t LATE_ACQUIRE_FRAMES = 2;
+
+ EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
+
+ insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
+ for (size_t i = 0; i < LATE_ACQUIRE_FRAMES; i++) {
+ mTimeStats->incrementLatchSkipped(LAYER_ID_0, TimeStats::LatchSkipReason::LateAcquire);
+ }
+ insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
+
+ const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
+ const std::string expectedResult = "lateAcquireFrames = " + std::to_string(LATE_ACQUIRE_FRAMES);
+ EXPECT_THAT(result, HasSubstr(expectedResult));
+}
+
+TEST_F(TimeStatsTest, canIncreaseBadDesiredPresent) {
+ // this stat is not in the proto so verify by checking the string dump
+ constexpr size_t BAD_DESIRED_PRESENT_FRAMES = 2;
+
+ EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
+
+ insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000);
+ for (size_t i = 0; i < BAD_DESIRED_PRESENT_FRAMES; i++) {
+ mTimeStats->incrementBadDesiredPresent(LAYER_ID_0);
+ }
+ insertTimeRecord(NORMAL_SEQUENCE_2, LAYER_ID_0, 2, 2000000);
+
+ const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING));
+ const std::string expectedResult =
+ "badDesiredPresentFrames = " + std::to_string(BAD_DESIRED_PRESENT_FRAMES);
+ EXPECT_THAT(result, HasSubstr(expectedResult));
+}
+
TEST_F(TimeStatsTest, canIncreaseClientCompositionReusedFrames) {
// this stat is not in the proto so verify by checking the string dump
constexpr size_t CLIENT_COMPOSITION_REUSED_FRAMES = 2;
@@ -665,7 +700,7 @@
EXPECT_EQ(0, globalProto.stats_size());
}
-TEST_F(TimeStatsTest, canClearClientCompositionSkippedFrames) {
+TEST_F(TimeStatsTest, canClearClientCompositionReusedFrames) {
// this stat is not in the proto so verify by checking the string dump
EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty());
ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionReusedFrames());
diff --git a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
index d1df08c..2720537 100644
--- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
+++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
@@ -40,6 +40,8 @@
MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, nsecs_t));
MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, const std::shared_ptr<FenceTime>&));
MOCK_METHOD4(setPostTime, void(int32_t, uint64_t, const std::string&, nsecs_t));
+ MOCK_METHOD2(incrementLatchSkipped, void(int32_t layerId, LatchSkipReason reason));
+ MOCK_METHOD1(incrementBadDesiredPresent, void(int32_t layerId));
MOCK_METHOD3(setLatchTime, void(int32_t, uint64_t, nsecs_t));
MOCK_METHOD3(setDesiredTime, void(int32_t, uint64_t, nsecs_t));
MOCK_METHOD3(setAcquireTime, void(int32_t, uint64_t, nsecs_t));