Merge "Trace SF skipped frame." into main (2ae4e980) · Commits · e / os / platform_frameworks_native

services/surfaceflinger/FrameTimeline/FrameTimeline.cpp

+66 −3

Original line number	Diff line number	Diff line
		@@ -1074,6 +1074,66 @@ void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid,
		});
		}

		void FrameTimeline::DisplayFrame::addSkippedFrame(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
		nsecs_t previousActualPresentTime) const {
		nsecs_t skippedFrameStartTime = 0, skippedFramePresentTime = 0;
		const constexpr float kThresh = 0.5f;
		const constexpr float kRange = 1.5f;
		for (auto& surfaceFrame : mSurfaceFrames) {
		if (previousActualPresentTime != 0 &&
		static_cast<float>(mSurfaceFlingerActuals.presentTime - previousActualPresentTime) >=
		static_cast<float>(mRenderRate.getPeriodNsecs()) * kRange &&
		static_cast<float>(surfaceFrame->getPredictions().presentTime) <=
		(static_cast<float>(mSurfaceFlingerActuals.presentTime) -
		kThresh * static_cast<float>(mRenderRate.getPeriodNsecs())) &&
		static_cast<float>(surfaceFrame->getPredictions().presentTime) >=
		(static_cast<float>(previousActualPresentTime) -
		kThresh * static_cast<float>(mRenderRate.getPeriodNsecs()))) {
		skippedFrameStartTime = surfaceFrame->getPredictions().endTime;
		skippedFramePresentTime = surfaceFrame->getPredictions().presentTime;
		break;
		}
		}

		// add slice
		if (skippedFrameStartTime != 0 && skippedFramePresentTime != 0) {
		int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();

		// Actual timeline start
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
		packet->set_timestamp(static_cast<uint64_t>(skippedFrameStartTime + monoBootOffset));

		auto* event = packet->set_frame_timeline_event();
		auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();

		actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);

		actualDisplayFrameStartEvent->set_token(0);
		actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
		actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
		FrameReadyMetadata::OnTimeFinish);
		actualDisplayFrameStartEvent->set_gpu_composition(false);
		actualDisplayFrameStartEvent->set_prediction_type(toProto(PredictionState::Valid));
		actualDisplayFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
		actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(JankType::Dropped));
		});

		// Actual timeline end
		FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
		auto packet = ctx.NewTracePacket();
		packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
		packet->set_timestamp(static_cast<uint64_t>(skippedFramePresentTime + monoBootOffset));

		auto* event = packet->set_frame_timeline_event();
		auto* actualDisplayFrameEndEvent = event->set_frame_end();

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

		void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid,
		nsecs_t monoBootOffset) const {
		int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
		@@ -1115,7 +1175,8 @@ void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid,
		});
		}

		void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const {
		void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
		nsecs_t previousActualPresentTime) const {
		if (mSurfaceFrames.empty()) {
		// We don't want to trace display frames without any surface frames updates as this cannot
		// be janky
		@@ -1138,6 +1199,8 @@ void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBoo
		for (auto& surfaceFrame : mSurfaceFrames) {
		surfaceFrame->trace(mToken, monoBootOffset);
		}

		addSkippedFrame(surfaceFlingerPid, monoBootOffset, previousActualPresentTime);
		}

		float FrameTimeline::computeFps(const std::unordered_set<int32_t>& layerIds) {
		@@ -1229,7 +1292,7 @@ void FrameTimeline::flushPendingPresentFences() {
		const nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
		auto& displayFrame = pendingPresentFence.second;
		displayFrame->onPresent(signalTime, mPreviousPresentTime);
		displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);
		displayFrame->trace(mSurfaceFlingerPid, monoBootOffset, mPreviousPresentTime);
		mPendingPresentFences.erase(mPendingPresentFences.begin());
		}

		@@ -1245,7 +1308,7 @@ void FrameTimeline::flushPendingPresentFences() {

		auto& displayFrame = pendingPresentFence.second;
		displayFrame->onPresent(signalTime, mPreviousPresentTime);
		displayFrame->trace(mSurfaceFlingerPid, monoBootOffset);
		displayFrame->trace(mSurfaceFlingerPid, monoBootOffset, mPreviousPresentTime);
		mPreviousPresentTime = signalTime;

		mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));

services/surfaceflinger/FrameTimeline/FrameTimeline.h

+4 −1

Original line number	Diff line number	Diff line
		@@ -378,7 +378,8 @@ public:
		// Emits a packet for perfetto tracing. The function body will be executed only if tracing
		// is enabled. monoBootOffset is the difference between SYSTEM_TIME_BOOTTIME
		// and SYSTEM_TIME_MONOTONIC.
		void trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;
		void trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
		nsecs_t previousActualPresentTime) const;
		// Sets the token, vsyncPeriod, predictions and SF start time.
		void onSfWakeUp(int64_t token, Fps refreshRate, Fps renderRate,
		std::optional<TimelineItem> predictions, nsecs_t wakeUpTime);
		@@ -411,6 +412,8 @@ public:
		void dump(std::string& result, nsecs_t baseTime) const;
		void tracePredictions(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;
		void traceActuals(pid_t surfaceFlingerPid, nsecs_t monoBootOffset) const;
		void addSkippedFrame(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
		nsecs_t previousActualPresentTime) const;
		void classifyJank(nsecs_t& deadlineDelta, nsecs_t& deltaToVsync,
		nsecs_t previousPresentTime);

services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp

+88 −1

Original line number	Diff line number	Diff line
		@@ -14,7 +14,6 @@
		* limitations under the License.
		*/


		#include "gmock/gmock-spec-builders.h"
		#include "mock/MockTimeStats.h"
		#undef LOG_TAG
		@@ -1059,6 +1058,94 @@ void validateTraceEvent(const ProtoFrameEnd& received, const ProtoFrameEnd& sour
		EXPECT_EQ(received.cookie(), source.cookie());
		}

		TEST_F(FrameTimelineTest, traceDisplayFrameSkipped) {
		// setup 2 display frames
		// DF 1: [22,40] -> [5, 40]
		// DF : [36, 70] (Skipped one, added by the trace)
		// DF 2: [82, 100] -> SF [25, 70]
		auto tracingSession = getTracingSessionForTest();
		tracingSession->StartBlocking();
		int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 30, 40});
		int64_t sfToken2 = mTokenManager->generateTokenForPredictions({82, 90, 100});
		int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({5, 16, 40});
		int64_t surfaceFrameToken2 = mTokenManager->generateTokenForPredictions({25, 36, 70});
		auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);

		int64_t traceCookie = snoopCurrentTraceCookie();

		// set up 1st display frame
		FrameTimelineInfo ftInfo1;
		ftInfo1.vsyncId = surfaceFrameToken1;
		ftInfo1.inputEventId = sInputEventId;
		auto surfaceFrame1 =
		mFrameTimeline->createSurfaceFrameForToken(ftInfo1, sPidOne, sUidOne, sLayerIdOne,
		sLayerNameOne, sLayerNameOne,
		/isBuffer/ true, sGameMode);
		surfaceFrame1->setAcquireFenceTime(16);
		mFrameTimeline->setSfWakeUp(sfToken1, 22, RR_11, RR_30);
		surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);
		mFrameTimeline->addSurfaceFrame(surfaceFrame1);
		mFrameTimeline->setSfPresent(30, presentFence1);
		presentFence1->signalForTest(40);

		// Trigger a flush by finalizing the next DisplayFrame
		auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
		FrameTimelineInfo ftInfo2;
		ftInfo2.vsyncId = surfaceFrameToken2;
		ftInfo2.inputEventId = sInputEventId;
		auto surfaceFrame2 =
		mFrameTimeline->createSurfaceFrameForToken(ftInfo2, sPidOne, sUidOne, sLayerIdOne,
		sLayerNameOne, sLayerNameOne,
		/isBuffer/ true, sGameMode);

		// set up 2nd display frame
		surfaceFrame2->setAcquireFenceTime(36);
		mFrameTimeline->setSfWakeUp(sfToken2, 82, RR_11, RR_30);
		surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented);
		mFrameTimeline->addSurfaceFrame(surfaceFrame2);
		mFrameTimeline->setSfPresent(90, presentFence2);
		presentFence2->signalForTest(100);

		// the token of skipped Display Frame
		auto protoSkippedActualDisplayFrameStart =
		createProtoActualDisplayFrameStart(traceCookie + 9, 0, kSurfaceFlingerPid,
		FrameTimelineEvent::PRESENT_DROPPED, true, false,
		FrameTimelineEvent::JANK_DROPPED,
		FrameTimelineEvent::PREDICTION_VALID);
		auto protoSkippedActualDisplayFrameEnd = createProtoFrameEnd(traceCookie + 9);

		// Trigger a flush by finalizing the next DisplayFrame
		addEmptyDisplayFrame();
		flushTrace();
		tracingSession->StopBlocking();

		auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
		// 8 Valid Display Frames + 8 Valid Surface Frames + 2 Skipped Display Frames
		EXPECT_EQ(packets.size(), 18u);

		// Packet - 16: Actual skipped Display Frame Start
		// the timestamp should be equal to the 2nd expected surface frame's end time
		const auto& packet16 = packets[16];
		ASSERT_TRUE(packet16.has_timestamp());
		EXPECT_EQ(packet16.timestamp(), 36u);
		ASSERT_TRUE(packet16.has_frame_timeline_event());

		const auto& event16 = packet16.frame_timeline_event();
		const auto& actualSkippedDisplayFrameStart = event16.actual_display_frame_start();
		validateTraceEvent(actualSkippedDisplayFrameStart, protoSkippedActualDisplayFrameStart);

		// Packet - 17: Actual skipped Display Frame End
		// the timestamp should be equal to the 2nd expected surface frame's present time
		const auto& packet17 = packets[17];
		ASSERT_TRUE(packet17.has_timestamp());
		EXPECT_EQ(packet17.timestamp(), 70u);
		ASSERT_TRUE(packet17.has_frame_timeline_event());

		const auto& event17 = packet17.frame_timeline_event();
		const auto& actualSkippedDisplayFrameEnd = event17.frame_end();
		validateTraceEvent(actualSkippedDisplayFrameEnd, protoSkippedActualDisplayFrameEnd);
		}

		TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) {
		auto tracingSession = getTracingSessionForTest();
		auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);