Merge "Trace SF skipped frame." into main

3 files changed, 158 insertions, 5 deletions

diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index 1b1307b13a..dfbb55dacc 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -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));
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index 538ea1288b..6598e218fd 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -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);
 
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 636d852651..e0400280fe 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 @@ 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);