Trace predictionExpired and dropped frames properly
Allowing frames with prediction expired causes a undesirable skew in the
trace. Since the timestamps are zero for this case, the trace packets
are also sent out with zero timestamp. These zero timestamps are seen as
the earliest possible time in a trace and hence make it look like the
trace contains 1000s of seconds of data while it actually doesn't.
This change addresses this issue by making SurfaceFrames not send any
expected timeline packets if prediction is expired. For actual timeline
packets, we apply a delta to the end time so that it looks like the
frame has a start and an end.
For dropped SurfaceFrames, we don't have an actual end time so far. This
change adds a dropTime to the SurfaceFrame so that we can keep track of
it in trace and dumpsys.
Bug: 179905685
Test: libsurfaceflinger_unittest:FrameTimelineTest
Change-Id: I573037be27f8a74670a65cad791841fa6ed75e20
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index eb0c724..444f756 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -30,6 +30,7 @@
using base::StringAppendF;
using FrameTimelineEvent = perfetto::protos::pbzero::FrameTimelineEvent;
+using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
void dumpTable(std::string& result, TimelineItem predictions, TimelineItem actuals,
const std::string& indent, PredictionState predictionState, nsecs_t baseTime) {
@@ -305,11 +306,17 @@
std::scoped_lock lock(mMutex);
mActualQueueTime = actualQueueTime;
}
+
void SurfaceFrame::setAcquireFenceTime(nsecs_t acquireFenceTime) {
std::scoped_lock lock(mMutex);
mActuals.endTime = std::max(acquireFenceTime, mActualQueueTime);
}
+void SurfaceFrame::setDropTime(nsecs_t dropTime) {
+ std::scoped_lock lock(mMutex);
+ mDropTime = dropTime;
+}
+
void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchTime) {
std::scoped_lock lock(mMutex);
LOG_ALWAYS_FATAL_IF(mPresentState != PresentState::Unknown,
@@ -343,6 +350,11 @@
return mActuals;
}
+PredictionState SurfaceFrame::getPredictionState() const {
+ std::scoped_lock lock(mMutex);
+ return mPredictionState;
+}
+
SurfaceFrame::PresentState SurfaceFrame::getPresentState() const {
std::scoped_lock lock(mMutex);
return mPresentState;
@@ -358,6 +370,11 @@
return mFrameReadyMetadata;
}
+nsecs_t SurfaceFrame::getDropTime() const {
+ std::scoped_lock lock(mMutex);
+ return mDropTime;
+}
+
void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) const {
std::scoped_lock lock(mMutex);
StringAppendF(&result, "%s", indent.c_str());
@@ -377,6 +394,12 @@
StringAppendF(&result, "%s", indent.c_str());
StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str());
StringAppendF(&result, "%s", indent.c_str());
+ if (mPresentState == PresentState::Dropped) {
+ std::chrono::nanoseconds dropTime(mDropTime - baseTime);
+ StringAppendF(&result, "Drop time : %10f\n",
+ std::chrono::duration<double, std::milli>(dropTime).count());
+ StringAppendF(&result, "%s", indent.c_str());
+ }
StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str());
StringAppendF(&result, "%s", indent.c_str());
StringAppendF(&result, "Jank Type : %s\n", jankTypeBitmaskToString(mJankType).c_str());
@@ -500,27 +523,12 @@
displayDeadlineDelta, displayPresentDelta, deadlineDelta});
}
-/**
- * TODO(b/178637512): add inputEventId to the perfetto trace.
- */
-void SurfaceFrame::trace(int64_t displayFrameToken) {
- using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
-
+void SurfaceFrame::tracePredictions(int64_t displayFrameToken) const {
int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
- bool missingToken = false;
+
// Expected timeline start
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
std::scoped_lock lock(mMutex);
- if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
- ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
- missingToken = true;
- return;
- } else if (displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
- ALOGD("Cannot trace SurfaceFrame - %s with invalid displayFrameToken",
- mLayerName.c_str());
- missingToken = true;
- return;
- }
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
@@ -537,12 +545,6 @@
expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
});
- if (missingToken) {
- // If one packet can't be traced because of missing token, then no packets can be traced.
- // Exit early in this case.
- return;
- }
-
// Expected timeline end
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
std::scoped_lock lock(mMutex);
@@ -555,15 +557,26 @@
expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
});
+}
+void SurfaceFrame::traceActuals(int64_t displayFrameToken) const {
int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+
// Actual timeline start
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
std::scoped_lock lock(mMutex);
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
// Actual start time is not yet available, so use expected start instead
- packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
+ 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.
+ packet->set_timestamp(
+ static_cast<uint64_t>(mActuals.endTime - kPredictionExpiredStartTimeDelta));
+ } else {
+ packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
+ }
auto* event = packet->set_frame_timeline_event();
auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
@@ -588,12 +601,17 @@
actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
});
+
// 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_MONOTONIC);
- packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
+ if (mPresentState == PresentState::Dropped) {
+ packet->set_timestamp(static_cast<uint64_t>(mDropTime));
+ } else {
+ packet->set_timestamp(static_cast<uint64_t>(mActuals.endTime));
+ }
auto* event = packet->set_frame_timeline_event();
auto* actualSurfaceFrameEndEvent = event->set_frame_end();
@@ -602,6 +620,23 @@
});
}
+/**
+ * TODO(b/178637512): add inputEventId to the perfetto trace.
+ */
+void SurfaceFrame::trace(int64_t displayFrameToken) const {
+ if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID ||
+ displayFrameToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
+ // No packets can be traced with a missing token.
+ return;
+ }
+ if (getPredictionState() != PredictionState::Expired) {
+ // Expired predictions have zeroed timestamps. This cannot be used in any meaningful way in
+ // a trace.
+ tracePredictions(displayFrameToken);
+ }
+ traceActuals(displayFrameToken);
+}
+
namespace impl {
int64_t TokenManager::generateTokenForPredictions(TimelineItem&& predictions) {
@@ -750,6 +785,11 @@
void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) {
mSurfaceFlingerActuals.presentTime = signalTime;
+ if (mPredictionState == PredictionState::Expired) {
+ // Cannot do jank classification with expired predictions
+ mJankType = JankType::Unknown;
+ return;
+ }
// Delta between the expected present and the actual present
const nsecs_t presentDelta =
@@ -836,17 +876,12 @@
}
}
-void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
+void FrameTimeline::DisplayFrame::tracePredictions(pid_t surfaceFlingerPid) const {
int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
- bool missingToken = false;
+
// Expected timeline start
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
auto packet = ctx.NewTracePacket();
- if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
- ALOGD("Cannot trace DisplayFrame with invalid token");
- missingToken = true;
- return;
- }
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
@@ -859,12 +894,6 @@
expectedDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
});
- if (missingToken) {
- // If one packet can't be traced because of missing token, then no packets can be traced.
- // Exit early in this case.
- return;
- }
-
// Expected timeline end
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
auto packet = ctx.NewTracePacket();
@@ -876,9 +905,12 @@
expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
});
+}
+void FrameTimeline::DisplayFrame::traceActuals(pid_t surfaceFlingerPid) const {
int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
- // Expected timeline start
+
+ // Actual timeline start
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
@@ -898,7 +930,8 @@
actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
});
- // Expected timeline end
+
+ // Actual timeline end
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
@@ -909,6 +942,21 @@
actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
});
+}
+
+void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
+ if (mToken == FrameTimelineInfo::INVALID_VSYNC_ID) {
+ // DisplayFrame should not have an invalid token.
+ ALOGE("Cannot trace DisplayFrame with invalid token");
+ return;
+ }
+
+ if (mPredictionState == PredictionState::Valid) {
+ // Expired and unknown predictions have zeroed timestamps. This cannot be used in any
+ // meaningful way in a trace.
+ tracePredictions(surfaceFlingerPid);
+ }
+ traceActuals(surfaceFlingerPid);
for (auto& surfaceFrame : mSurfaceFrames) {
surfaceFrame->trace(mToken);
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index 4739106..8f3157d 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -171,10 +171,12 @@
TimelineItem getPredictions() const { return mPredictions; };
// Actual timestamps of the app are set individually at different functions.
// Start time (if the app provides) and Queue time are accessible after queueing the frame,
- // whereas Acquire Fence time is available only during latch.
+ // whereas Acquire Fence time is available only during latch. Drop time is available at the time
+ // the buffer was dropped.
void setActualStartTime(nsecs_t actualStartTime);
void setActualQueueTime(nsecs_t actualQueueTime);
void setAcquireFenceTime(nsecs_t acquireFenceTime);
+ void setDropTime(nsecs_t dropTime);
void setPresentState(PresentState presentState, nsecs_t lastLatchTime = 0);
void setRenderRate(Fps renderRate);
@@ -192,17 +194,27 @@
// Emits a packet for perfetto tracing. The function body will be executed only if tracing is
// enabled. The displayFrameToken is needed to link the SurfaceFrame to the corresponding
// DisplayFrame at the trace processor side.
- void trace(int64_t displayFrameToken);
+ void trace(int64_t displayFrameToken) const;
- // Getter functions used only by FrameTimelineTests
+ // Getter functions used only by FrameTimelineTests and SurfaceFrame internally
TimelineItem getActuals() const;
pid_t getOwnerPid() const { return mOwnerPid; };
- PredictionState getPredictionState() const { return mPredictionState; };
+ PredictionState getPredictionState() const;
PresentState getPresentState() const;
FrameReadyMetadata getFrameReadyMetadata() const;
FramePresentMetadata getFramePresentMetadata() const;
+ nsecs_t getDropTime() const;
+
+ // For prediction expired frames, this delta is subtracted from the actual end time to get a
+ // start time decent enough to see in traces.
+ // TODO(b/172587309): Remove this when we have actual start times.
+ static constexpr nsecs_t kPredictionExpiredStartTimeDelta =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(2ms).count();
private:
+ void tracePredictions(int64_t displayFrameToken) const;
+ void traceActuals(int64_t displayFrameToken) const;
+
const int64_t mToken;
const int32_t mInputEventId;
const pid_t mOwnerPid;
@@ -216,6 +228,7 @@
std::shared_ptr<TimeStats> mTimeStats;
const JankClassificationThresholds mJankClassificationThresholds;
nsecs_t mActualQueueTime GUARDED_BY(mMutex) = 0;
+ nsecs_t mDropTime GUARDED_BY(mMutex) = 0;
mutable std::mutex mMutex;
// Bitmask for the type of jank
int32_t mJankType GUARDED_BY(mMutex) = JankType::None;
@@ -359,6 +372,8 @@
private:
void dump(std::string& result, nsecs_t baseTime) const;
+ void tracePredictions(pid_t surfaceFlingerPid) const;
+ void traceActuals(pid_t surfaceFlingerPid) const;
int64_t mToken = FrameTimelineInfo::INVALID_VSYNC_ID;