Trace SF skipped frame.
Bug: 273701290
Test: FrameTimelineTest#traceDisplayFrameSkipped; https://screenshot.googleplex.com/4As43np7DoF6Dxm
Change-Id: I0604ab3d15ef94351f9a592920c56ab00ef51b23
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index 1b1307b..dfbb55d 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -1074,6 +1074,66 @@
});
}
+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::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 @@
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 @@
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 @@
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));
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index 538ea12..6598e21 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -378,7 +378,8 @@
// 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 @@
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);
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 636d852..e040028 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -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 @@
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);