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));