Merge "[TimeStats] Expose pathological latch counters" (62748383) · Commits · e / os / platform_frameworks_native

services/surfaceflinger/BufferQueueLayer.cpp

+12 −1

Original line number	Diff line number	Diff line
		@@ -117,6 +117,10 @@ bool BufferQueueLayer::shouldPresentNow(nsecs_t expectedPresentTime) const {
		"relative to expectedPresent %" PRId64,
		getDebugName(), addedTime, expectedPresentTime);

		if (!isPlausible) {
		mFlinger->mTimeStats->incrementBadDesiredPresent(getSequence());
		}

		const bool isDue = addedTime < expectedPresentTime;
		return isDue \|\| !isPlausible;
		}
		@@ -159,7 +163,14 @@ bool BufferQueueLayer::fenceHasSignaled() const {
		// 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 {

services/surfaceflinger/BufferStateLayer.cpp

+8 −1

Original line number	Diff line number	Diff line
		@@ -403,7 +403,14 @@ bool BufferStateLayer::fenceHasSignaled() const {
		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 {

services/surfaceflinger/TimeStats/TimeStats.cpp

+35 −0

Original line number	Diff line number	Diff line
		@@ -363,7 +363,12 @@ void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) {
		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);
		@@ -477,6 +482,36 @@ void TimeStats::setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latc
		}
		}

		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;

services/surfaceflinger/TimeStats/TimeStats.h

+16 −0

Original line number	Diff line number	Diff line
		@@ -70,6 +70,18 @@ public:
		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 @@ class TimeStats : public android::TimeStats {
		// 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;
		};
		@@ -202,6 +216,8 @@ public:
		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,

services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp

+2 −0

Original line number	Diff line number	Diff line
		@@ -83,6 +83,8 @@ std::string TimeStatsHelper::TimeStatsLayer::toString() const {
		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());