Merge "Trace predictionExpired and dropped frames properly" into sc-dev (55ee8750) · Commits · e / os / android_frameworks_native-old

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+88 −40

Original line number	Diff line number	Diff line
		@@ -30,6 +30,7 @@ namespace android::frametimeline {

		using base::StringAppendF;
		using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
		using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;

		void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
		const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
		@@ -305,11 +306,17 @@ void SurfaceFrame::setActualQueueTime(nsecs_t actualQueueTime) {
		std::scoped_lock lock(mMutex);
		mActualQueueTime = actualQueueTime;
		}

		void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
		std::scoped_lock lock(mMutex);
		mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
		}

		void SurfaceFrame::setDropTime(nsecs_t dropTime) {
		std::scoped_lock lock(mMutex);
		mDropTime = dropTime;
		}

		void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
		std::scoped_lock lock(mMutex);
		LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
		@@ -348,6 +355,11 @@ TimelineItem SurfaceFrame::getActuals() const {
		return mActuals;
		}

		PredictionState SurfaceFrame::getPredictionState() const {
		std::scoped_lock lock(mMutex);
		return mPredictionState;
		}

		SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
		std::scoped_lock lock(mMutex);
		return mPresentState;
		@@ -363,6 +375,11 @@ FrameReadyMetadata SurfaceFrame::getFrameReadyMetadata() const {
		return mFrameReadyMetadata;
		}

		nsecs_t SurfaceFrame::getDropTime() const {
		std::scoped_lock lock(mMutex);
		return mDropTime;
		}

		void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
		std::scoped_lock lock(mMutex);
		StringAppendF(&result, "%s", indent.c_str());
		@@ -382,6 +399,12 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t
		StringAppendF(&result, "%s", indent.c_str());
		StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
		StringAppendF(&result, "%s", indent.c_str());
		if (mPresentState == PresentState::Dropped) {
		std::chrono::nanoseconds dropTime(mDropTime - baseTime);
		StringAppendF(&result, "Drop time : %10f\n",
		std::chrono::duration<double, std::milli>(dropTime).count());
		StringAppendF(&result, "%s", indent.c_str());
		}
		StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
		StringAppendF(&result, "%s", indent.c_str());
		StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
		@@ -505,27 +528,12 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType,
		displayDeadlineDelta, displayPresentDelta, deadlineDelta});
		}

		/**
		* TODO(b/178637512): add inputEventId to the perfetto trace.
		*/
		void SurfaceFrame::trace(int64_t displayFrameToken) {
		using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;

		void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
		int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
		bool missingToken = false;

		// Expected timeline start
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		std::scoped_lock lock(mMutex);
		if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
		ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
		missingToken = true;
		return;
		} else if (displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
		ALOGD("Cannot trace SurfaceFrame - %s with invalid displayFrameToken",
		mLayerName.c_str());
		missingToken = true;
		return;
		}
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
		@@ -542,12 +550,6 @@ void SurfaceFrame::trace(int64_t displayFrameToken) {
		expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
		});

		if (missingToken) {
		// If one packet can't be traced because of missing token, then no packets can be traced.
		// Exit early in this case.
		return;
		}

		// Expected timeline end
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		std::scoped_lock lock(mMutex);
		@@ -560,15 +562,26 @@ void SurfaceFrame::trace(int64_t displayFrameToken) {

		expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
		});
		}

		void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {
		int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();

		// Actual timeline start
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		std::scoped_lock lock(mMutex);
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		// Actual start time is not yet available, so use expected start instead
		if (mPredictionState == PredictionState::Expired) {
		// If prediction is expired, we can't use the predicted start time. Instead, just use a
		// start time a little earlier than the end time so that we have some info about this
		// frame in the trace.
		packet->set_timestamp(
		static_cast<uint64_t>(mActuals.endTime - kPredictionExpiredStartTimeDelta));
		} else {
		packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
		}

		auto* event = packet->set_frame_timeline_event();
		auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
		@@ -593,12 +606,17 @@ void SurfaceFrame::trace(int64_t displayFrameToken) {
		actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
		actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
		});

		// Actual timeline end
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		std::scoped_lock lock(mMutex);
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		if (mPresentState == PresentState::Dropped) {
		packet->set_timestamp(static_cast<uint64_t>(mDropTime));
		} else {
		packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
		}

		auto* event = packet->set_frame_timeline_event();
		auto* actualSurfaceFrameEndEvent = event->set_frame_end();
		@@ -607,6 +625,23 @@ void SurfaceFrame::trace(int64_t displayFrameToken) {
		});
		}

		/**
		* TODO(b/178637512): add inputEventId to the perfetto trace.
		*/
		void SurfaceFrame::trace(int64_t displayFrameToken) const {
		if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID \|\|
		displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
		// No packets can be traced with a missing token.
		return;
		}
		if (getPredictionState() != PredictionState::Expired) {
		// Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
		// a trace.
		tracePredictions(displayFrameToken);
		}
		traceActuals(displayFrameToken);
		}

		namespace impl {

		int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
		@@ -755,6 +790,11 @@ void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) {

		void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
		mSurfaceFlingerActuals.presentTime = signalTime;
		if (mPredictionState == PredictionState::Expired) {
		// Cannot do jank classification with expired predictions
		mJankType = JankType::Unknown;
		return;
		}

		// Delta between the expected present and the actual present
		const nsecs_t presentDelta =
		@@ -841,17 +881,12 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
		}
		}

		void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
		void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {
		int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
		bool missingToken = false;

		// Expected timeline start
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
		ALOGD("Cannot trace DisplayFrame with invalid token");
		missingToken = true;
		return;
		}
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));

		@@ -864,12 +899,6 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
		expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
		});

		if (missingToken) {
		// If one packet can't be traced because of missing token, then no packets can be traced.
		// Exit early in this case.
		return;
		}

		// Expected timeline end
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		@@ -881,9 +910,12 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {

		expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
		});
		}

		void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {
		int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
		// Expected timeline start

		// Actual timeline start
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		@@ -903,7 +935,8 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
		actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
		actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
		});
		// Expected timeline end

		// Actual timeline end
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
		@@ -914,6 +947,21 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {

		actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
		});
		}

		void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
		if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
		// DisplayFrame should not have an invalid token.
		ALOGE("Cannot trace DisplayFrame with invalid token");
		return;
		}

		if (mPredictionState == PredictionState::Valid) {
		// Expired and unknown predictions have zeroed timestamps. This cannot be used in any
		// meaningful way in a trace.
		tracePredictions(surfaceFlingerPid);
		}
		traceActuals(surfaceFlingerPid);

		for (auto& surfaceFrame : mSurfaceFrames) {
		surfaceFrame->trace(mToken);

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+19 −4

Original line number	Diff line number	Diff line
		@@ -171,10 +171,12 @@ public:
		TimelineItem getPredictions() const { return mPredictions; };
		// Actual timestamps of the app are set individually at different functions.
		// Start time (if the app provides) and Queue time are accessible after queueing the frame,
		// whereas Acquire Fence time is available only during latch.
		// whereas Acquire Fence time is available only during latch. Drop time is available at the time
		// the buffer was dropped.
		void setActualStartTime(nsecs_t actualStartTime);
		void setActualQueueTime(nsecs_t actualQueueTime);
		void setAcquireFenceTime(nsecs_t acquireFenceTime);
		void setDropTime(nsecs_t dropTime);
		void setPresentState(PresentState presentState, nsecs_t lastLatchTime = 0);
		void setRenderRate(Fps renderRate);

		@@ -192,17 +194,27 @@ public:
		// Emits a packet for perfetto tracing. The function body will be executed only if tracing is
		// enabled. The displayFrameToken is needed to link the SurfaceFrame to the corresponding
		// DisplayFrame at the trace processor side.
		void trace(int64_t displayFrameToken);
		void trace(int64_t displayFrameToken) const;

		// Getter functions used only by FrameTimelineTests
		// Getter functions used only by FrameTimelineTests and SurfaceFrame internally
		TimelineItem getActuals() const;
		pid_t getOwnerPid() const { return mOwnerPid; };
		PredictionState getPredictionState() const { return mPredictionState; };
		PredictionState getPredictionState() const;
		PresentState getPresentState() const;
		FrameReadyMetadata getFrameReadyMetadata() const;
		FramePresentMetadata getFramePresentMetadata() const;
		nsecs_t getDropTime() const;

		// For prediction expired frames, this delta is subtracted from the actual end time to get a
		// start time decent enough to see in traces.
		// TODO(b/172587309): Remove this when we have actual start times.
		static constexpr nsecs_t kPredictionExpiredStartTimeDelta =
		std::chrono::duration_cast<std::chrono::nanoseconds>(2ms).count();

		private:
		void tracePredictions(int64_t displayFrameToken) const;
		void traceActuals(int64_t displayFrameToken) const;

		const int64_t mToken;
		const int32_t mInputEventId;
		const pid_t mOwnerPid;
		@@ -216,6 +228,7 @@ private:
		std::shared_ptr<TimeStats> mTimeStats;
		const JankClassificationThresholds mJankClassificationThresholds;
		nsecs_t mActualQueueTime GUARDED_BY(mMutex) = 0;
		nsecs_t mDropTime GUARDED_BY(mMutex) = 0;
		mutable std::mutex mMutex;
		// Bitmask for the type of jank
		int32_t mJankType GUARDED_BY(mMutex) = JankType::None;
		@@ -359,6 +372,8 @@ public:

		private:
		void dump(std::string& result, nsecs_t baseTime) const;
		void tracePredictions(pid_t surfaceFlingerPid) const;
		void traceActuals(pid_t surfaceFlingerPid) const;

		int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID;

services/surfaceflinger/Layer.cpp

+1 −0

Original line number	Diff line number	Diff line
		@@ -1560,6 +1560,7 @@ void Layer::setFrameTimelineVsyncForBufferlessTransaction(const FrameTimelineInf

		void Layer::addSurfaceFrameDroppedForBuffer(
		std::shared_ptr<frametimeline::SurfaceFrame>& surfaceFrame) {
		surfaceFrame->setDropTime(systemTime());
		surfaceFrame->setPresentState(PresentState::Dropped);
		mFlinger->mFrameTimeline->addSurfaceFrame(surfaceFrame);
		}

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+306 −125

File changed.

Preview size limit exceeded, changes collapsed.

services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp

+5 −0

Original line number	Diff line number	Diff line
		@@ -157,8 +157,10 @@ public:
		sp<Fence> fence2(new Fence());
		auto acquireFence2 = fenceFactory.createFenceTimeForTest(fence2);
		sp<GraphicBuffer> buffer2{new GraphicBuffer(1, 1, HAL_PIXEL_FORMAT_RGBA_8888, 1, 0)};
		nsecs_t start = systemTime();
		layer->setBuffer(buffer2, fence2, 10, 20, false, mClientCache, 1, std::nullopt,
		{/vsyncId/ 1, /inputEventId/ 0});
		nsecs_t end = systemTime();
		acquireFence2->signalForTest(12);

		EXPECT_EQ(0u, layer->mCurrentState.bufferlessSurfaceFramesTX.size());
		@@ -171,6 +173,9 @@ public:

		EXPECT_EQ(1, droppedSurfaceFrame->getToken());
		EXPECT_EQ(PresentState::Dropped, droppedSurfaceFrame->getPresentState());
		EXPECT_EQ(0u, droppedSurfaceFrame->getActuals().endTime);
		auto dropTime = droppedSurfaceFrame->getDropTime();
		EXPECT_TRUE(dropTime > start && dropTime < end);

		EXPECT_EQ(1, presentedSurfaceFrame->getToken());
		EXPECT_EQ(PresentState::Presented, presentedSurfaceFrame->getPresentState());