SF: Do not trace FrameTimeline before start

Filter FrameTimeline events for frames started before the trace started.

Bug: 364194637
Test: manual
Flag: com.android.graphics.surfaceflinger.flags.filter_frames_before_trace_starts
Change-Id: I9185f384f306eddab1afc2ea9d7901dd70d2f1a2
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index 2311360..47b811b 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -38,6 +38,8 @@
 using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
 using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
 
+namespace {
+
 void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
                const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
     StringAppendF(&result, "%s", indent.c_str());
@@ -319,6 +321,16 @@
     return minTime;
 }
 
+bool shouldTraceForDataSource(const FrameTimelineDataSource::TraceContext& ctx, nsecs_t timestamp) {
+    if (auto ds = ctx.GetDataSourceLocked(); ds && ds->getStartTime() > timestamp) {
+        return false;
+    }
+
+    return true;
+}
+
+} // namespace
+
 int64_t TraceCookieCounter::getCookieForTracing() {
     return ++mTraceCookie;
 }
@@ -726,15 +738,24 @@
     classifyJankLocked(JankType::None, refreshRate, displayFrameRenderRate, nullptr);
 }
 
-void SurfaceFrame::tracePredictions(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
+void SurfaceFrame::tracePredictions(int64_t displayFrameToken, nsecs_t monoBootOffset,
+                                    bool filterFramesBeforeTraceStarts) const {
     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+    bool traced = false;
 
     // Expected timeline start
     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+        const auto timestamp = mPredictions.startTime;
+        if (filterFramesBeforeTraceStarts && !shouldTraceForDataSource(ctx, timestamp)) {
+            // Do not trace packets started before tracing starts.
+            return;
+        }
+        traced = true;
+
         std::scoped_lock lock(mMutex);
         auto packet = ctx.NewTracePacket();
         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
-        packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime + monoBootOffset));
+        packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
 
         auto* event = packet->set_frame_timeline_event();
         auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
@@ -748,42 +769,54 @@
         expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
     });
 
-    // Expected 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_BOOTTIME);
-        packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime + monoBootOffset));
+    if (traced) {
+        // Expected 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_BOOTTIME);
+            packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime + monoBootOffset));
 
-        auto* event = packet->set_frame_timeline_event();
-        auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
+            auto* event = packet->set_frame_timeline_event();
+            auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
 
-        expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
-    });
+            expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
+        });
+    }
 }
 
-void SurfaceFrame::traceActuals(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
+void SurfaceFrame::traceActuals(int64_t displayFrameToken, nsecs_t monoBootOffset,
+                                bool filterFramesBeforeTraceStarts) const {
     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+    bool traced = false;
 
     // Actual timeline start
     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+        const auto timestamp = [&]() {
+            std::scoped_lock lock(mMutex);
+            // 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.
+                nsecs_t endTime =
+                        (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
+                return endTime - kPredictionExpiredStartTimeDelta;
+            }
+
+            return mActuals.startTime == 0 ? mPredictions.startTime : mActuals.startTime;
+        }();
+
+        if (filterFramesBeforeTraceStarts && !shouldTraceForDataSource(ctx, timestamp)) {
+            // Do not trace packets started before tracing starts.
+            return;
+        }
+        traced = true;
+
         std::scoped_lock lock(mMutex);
         auto packet = ctx.NewTracePacket();
         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
-        // 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.
-            nsecs_t endTime =
-                    (mPresentState == PresentState::Dropped ? mDropTime : mActuals.endTime);
-            const auto timestamp = endTime - kPredictionExpiredStartTimeDelta;
-            packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
-        } else {
-            const auto timestamp =
-                    mActuals.startTime == 0 ? mPredictions.startTime : mActuals.startTime;
-            packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
-        }
+        packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
 
         auto* event = packet->set_frame_timeline_event();
         auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
@@ -812,28 +845,31 @@
         actualSurfaceFrameStartEvent->set_jank_severity_type(toProto(mJankSeverityType));
     });
 
-    // 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_BOOTTIME);
-        if (mPresentState == PresentState::Dropped) {
-            packet->set_timestamp(static_cast<uint64_t>(mDropTime + monoBootOffset));
-        } else {
-            packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime + monoBootOffset));
-        }
+    if (traced) {
+        // 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_BOOTTIME);
+            if (mPresentState == PresentState::Dropped) {
+                packet->set_timestamp(static_cast<uint64_t>(mDropTime + monoBootOffset));
+            } else {
+                packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime + monoBootOffset));
+            }
 
-        auto* event = packet->set_frame_timeline_event();
-        auto* actualSurfaceFrameEndEvent = event->set_frame_end();
+            auto* event = packet->set_frame_timeline_event();
+            auto* actualSurfaceFrameEndEvent = event->set_frame_end();
 
-        actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
-    });
+            actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
+        });
+    }
 }
 
 /**
  * TODO(b/178637512): add inputEventId to the perfetto trace.
  */
-void SurfaceFrame::trace(int64_t displayFrameToken, nsecs_t monoBootOffset) const {
+void SurfaceFrame::trace(int64_t displayFrameToken, nsecs_t monoBootOffset,
+                         bool filterFramesBeforeTraceStarts) const {
     if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
         displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
         // No packets can be traced with a missing token.
@@ -842,9 +878,9 @@
     if (getPredictionState() != PredictionState::Expired) {
         // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
         // a trace.
-        tracePredictions(displayFrameToken, monoBootOffset);
+        tracePredictions(displayFrameToken, monoBootOffset, filterFramesBeforeTraceStarts);
     }
-    traceActuals(displayFrameToken, monoBootOffset);
+    traceActuals(displayFrameToken, monoBootOffset, filterFramesBeforeTraceStarts);
 }
 
 namespace impl {
@@ -870,8 +906,12 @@
 }
 
 FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
-                             JankClassificationThresholds thresholds, bool useBootTimeClock)
+                             JankClassificationThresholds thresholds, bool useBootTimeClock,
+                             bool filterFramesBeforeTraceStarts)
       : mUseBootTimeClock(useBootTimeClock),
+        mFilterFramesBeforeTraceStarts(
+                FlagManager::getInstance().filter_frames_before_trace_starts() &&
+                filterFramesBeforeTraceStarts),
         mMaxDisplayFrames(kDefaultMaxDisplayFrames),
         mTimeStats(std::move(timeStats)),
         mSurfaceFlingerPid(surfaceFlingerPid),
@@ -1154,16 +1194,23 @@
     }
 }
 
-void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid,
-                                                   nsecs_t monoBootOffset) const {
+void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
+                                                   bool filterFramesBeforeTraceStarts) const {
     int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+    bool traced = false;
 
     // Expected timeline start
     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+        const auto timestamp = mSurfaceFlingerPredictions.startTime;
+        if (filterFramesBeforeTraceStarts && !shouldTraceForDataSource(ctx, timestamp)) {
+            // Do not trace packets started before tracing starts.
+            return;
+        }
+        traced = true;
+
         auto packet = ctx.NewTracePacket();
         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
-        packet->set_timestamp(
-                static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime + monoBootOffset));
+        packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
 
         auto* event = packet->set_frame_timeline_event();
         auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
@@ -1174,22 +1221,25 @@
         expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
     });
 
-    // Expected 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>(mSurfaceFlingerPredictions.endTime + monoBootOffset));
+    if (traced) {
+        // Expected 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>(mSurfaceFlingerPredictions.endTime + monoBootOffset));
 
-        auto* event = packet->set_frame_timeline_event();
-        auto* expectedDisplayFrameEndEvent = event->set_frame_end();
+            auto* event = packet->set_frame_timeline_event();
+            auto* expectedDisplayFrameEndEvent = event->set_frame_end();
 
-        expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
-    });
+            expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
+        });
+    }
 }
 
 void FrameTimeline::DisplayFrame::addSkippedFrame(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
-                                                  nsecs_t previousPredictionPresentTime) const {
+                                                  nsecs_t previousPredictionPresentTime,
+                                                  bool filterFramesBeforeTraceStarts) const {
     nsecs_t skippedFrameStartTime = 0, skippedFramePresentTime = 0;
     const constexpr float kThresh = 0.5f;
     const constexpr float kRange = 1.5f;
@@ -1215,9 +1265,17 @@
     // add slice
     if (skippedFrameStartTime != 0 && skippedFramePresentTime != 0) {
         int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+        bool traced = false;
 
         // Actual timeline start
         FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+            if (filterFramesBeforeTraceStarts &&
+                !shouldTraceForDataSource(ctx, skippedFrameStartTime)) {
+                // Do not trace packets started before tracing starts.
+                return;
+            }
+            traced = true;
+
             auto packet = ctx.NewTracePacket();
             packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
             packet->set_timestamp(static_cast<uint64_t>(skippedFrameStartTime + monoBootOffset));
@@ -1238,30 +1296,40 @@
             actualDisplayFrameStartEvent->set_jank_severity_type(toProto(JankSeverityType::None));
         });
 
-        // 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));
+        if (traced) {
+            // 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();
+                auto* event = packet->set_frame_timeline_event();
+                auto* actualDisplayFrameEndEvent = event->set_frame_end();
 
-            actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
-        });
+                actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
+            });
+        }
     }
 }
 
-void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid,
-                                               nsecs_t monoBootOffset) const {
+void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
+                                               bool filterFramesBeforeTraceStarts) const {
     int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+    bool traced = false;
 
     // Actual timeline start
     FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+        const auto timestamp = mSurfaceFlingerActuals.startTime;
+        if (filterFramesBeforeTraceStarts && !shouldTraceForDataSource(ctx, timestamp)) {
+            // Do not trace packets started before tracing starts.
+            return;
+        }
+        traced = true;
+
         auto packet = ctx.NewTracePacket();
         packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
-        packet->set_timestamp(
-                static_cast<uint64_t>(mSurfaceFlingerActuals.startTime + monoBootOffset));
+        packet->set_timestamp(static_cast<uint64_t>(timestamp + monoBootOffset));
 
         auto* event = packet->set_frame_timeline_event();
         auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
@@ -1280,22 +1348,25 @@
         actualDisplayFrameStartEvent->set_jank_severity_type(toProto(mJankSeverityType));
     });
 
-    // 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>(mSurfaceFlingerActuals.presentTime + monoBootOffset));
+    if (traced) {
+        // 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>(mSurfaceFlingerActuals.presentTime + monoBootOffset));
 
-        auto* event = packet->set_frame_timeline_event();
-        auto* actualDisplayFrameEndEvent = event->set_frame_end();
+            auto* event = packet->set_frame_timeline_event();
+            auto* actualDisplayFrameEndEvent = event->set_frame_end();
 
-        actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
-    });
+            actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
+        });
+    }
 }
 
 nsecs_t FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid, nsecs_t monoBootOffset,
-                                           nsecs_t previousPredictionPresentTime) const {
+                                           nsecs_t previousPredictionPresentTime,
+                                           bool filterFramesBeforeTraceStarts) const {
     if (mSurfaceFrames.empty()) {
         // We don't want to trace display frames without any surface frames updates as this cannot
         // be janky
@@ -1311,16 +1382,17 @@
     if (mPredictionState == PredictionState::Valid) {
         // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
         // meaningful way in a trace.
-        tracePredictions(surfaceFlingerPid, monoBootOffset);
+        tracePredictions(surfaceFlingerPid, monoBootOffset, filterFramesBeforeTraceStarts);
     }
-    traceActuals(surfaceFlingerPid, monoBootOffset);
+    traceActuals(surfaceFlingerPid, monoBootOffset, filterFramesBeforeTraceStarts);
 
     for (auto& surfaceFrame : mSurfaceFrames) {
-        surfaceFrame->trace(mToken, monoBootOffset);
+        surfaceFrame->trace(mToken, monoBootOffset, filterFramesBeforeTraceStarts);
     }
 
     if (FlagManager::getInstance().add_sf_skipped_frames_to_trace()) {
-        addSkippedFrame(surfaceFlingerPid, monoBootOffset, previousPredictionPresentTime);
+        addSkippedFrame(surfaceFlingerPid, monoBootOffset, previousPredictionPresentTime,
+                        filterFramesBeforeTraceStarts);
     }
     return mSurfaceFlingerPredictions.presentTime;
 }
@@ -1414,8 +1486,9 @@
         const nsecs_t signalTime = Fence::SIGNAL_TIME_INVALID;
         auto& displayFrame = pendingPresentFence.second;
         displayFrame->onPresent(signalTime, mPreviousActualPresentTime);
-        mPreviousPredictionPresentTime = displayFrame->trace(mSurfaceFlingerPid, monoBootOffset,
-                                                             mPreviousPredictionPresentTime);
+        mPreviousPredictionPresentTime =
+                displayFrame->trace(mSurfaceFlingerPid, monoBootOffset,
+                                    mPreviousPredictionPresentTime, mFilterFramesBeforeTraceStarts);
         mPendingPresentFences.erase(mPendingPresentFences.begin());
     }
 
@@ -1431,8 +1504,9 @@
 
         auto& displayFrame = pendingPresentFence.second;
         displayFrame->onPresent(signalTime, mPreviousActualPresentTime);
-        mPreviousPredictionPresentTime = displayFrame->trace(mSurfaceFlingerPid, monoBootOffset,
-                                                             mPreviousPredictionPresentTime);
+        mPreviousPredictionPresentTime =
+                displayFrame->trace(mSurfaceFlingerPid, monoBootOffset,
+                                    mPreviousPredictionPresentTime, mFilterFramesBeforeTraceStarts);
         mPreviousActualPresentTime = signalTime;
 
         mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i));