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;
diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp
index 6a28da3..f47ec30 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -1560,6 +1560,7 @@
void Layer::addSurfaceFrameDroppedForBuffer(
std::shared_ptr<frametimeline::SurfaceFrame>& surfaceFrame) {
+ surfaceFrame->setDropTime(systemTime());
surfaceFrame->setPresentState(PresentState::Dropped);
mFlinger->mFrameTimeline->addSurfaceFrame(surfaceFrame);
}
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index b3ab8f1..1c57e4c 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -106,6 +106,7 @@
void addEmptyDisplayFrame() {
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+ // Trigger a flushPresentFence by calling setSfPresent for the next frame
mFrameTimeline->setSfPresent(2500, presentFence1);
}
@@ -234,29 +235,26 @@
}
TEST_F(FrameTimelineTest, presentFenceSignaled_droppedFramesNotUpdated) {
- // Global increment
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
-
int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
- int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
auto surfaceFrame1 =
mFrameTimeline->createSurfaceFrameForToken({token1, sInputEventId}, sPidOne, sUidOne,
sLayerNameOne, sLayerNameOne);
// Set up the display frame
mFrameTimeline->setSfWakeUp(token1, 20, Fps::fromPeriodNsecs(11));
+ surfaceFrame1->setDropTime(12);
surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Dropped);
mFrameTimeline->addSurfaceFrame(surfaceFrame1);
mFrameTimeline->setSfPresent(25, presentFence1);
presentFence1->signalForTest(30);
- // Trigger a flush by calling setSfPresent for the next frame
- mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
+ addEmptyDisplayFrame();
auto& droppedSurfaceFrame = getSurfaceFrame(0, 0);
EXPECT_EQ(droppedSurfaceFrame.getPresentState(), SurfaceFrame::PresentState::Dropped);
+ EXPECT_EQ(0u, droppedSurfaceFrame.getActuals().endTime);
+ EXPECT_EQ(12u, droppedSurfaceFrame.getDropTime());
EXPECT_EQ(droppedSurfaceFrame.getActuals().presentTime, 0);
}
@@ -265,9 +263,7 @@
EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)).Times(2);
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
- int64_t surfaceFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 30});
- int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 60});
auto surfaceFrame1 =
mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne,
sUidOne, sLayerNameOne, sLayerNameOne);
@@ -290,16 +286,7 @@
EXPECT_EQ(presentedSurfaceFrame1.getActuals().presentTime, 0);
EXPECT_EQ(presentedSurfaceFrame2.getActuals().presentTime, 0);
- // Trigger a flush by finalizing the next DisplayFrame
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto surfaceFrame3 =
- mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne,
- sUidOne, sLayerNameOne, sLayerNameOne);
- mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(11));
- surfaceFrame3->setPresentState(SurfaceFrame::PresentState::Dropped);
- mFrameTimeline->addSurfaceFrame(surfaceFrame3);
- mFrameTimeline->setSfPresent(56, presentFence2);
- displayFrame = getDisplayFrame(0);
+ addEmptyDisplayFrame();
// Fences have flushed, so the present timestamps should be updated
EXPECT_EQ(displayFrame->getActuals().presentTime, 42);
@@ -587,10 +574,7 @@
TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) {
auto tracingSession = getTracingSessionForTest();
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
-
int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
- int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
auto surfaceFrame1 =
mFrameTimeline->createSurfaceFrameForToken({token1, sInputEventId}, sPidOne, sUidOne,
sLayerNameOne, sLayerNameOne);
@@ -602,10 +586,7 @@
mFrameTimeline->setSfPresent(25, presentFence1);
presentFence1->signalForTest(30);
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
+ addEmptyDisplayFrame();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
EXPECT_EQ(packets.size(), 0u);
@@ -616,7 +597,6 @@
// Layer specific increment
EXPECT_CALL(*mTimeStats, incrementJankyFrames(_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
tracingSession->StartBlocking();
int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
@@ -632,12 +612,7 @@
mFrameTimeline->setSfPresent(25, presentFence1);
presentFence1->signalForTest(30);
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
- presentFence2->signalForTest(55);
-
+ addEmptyDisplayFrame();
flushTrace();
tracingSession->StopBlocking();
@@ -649,22 +624,15 @@
TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) {
auto tracingSession = getTracingSessionForTest();
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
tracingSession->StartBlocking();
- int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
// Set up the display frame
mFrameTimeline->setSfWakeUp(-1, 20, Fps::fromPeriodNsecs(11));
mFrameTimeline->setSfPresent(25, presentFence1);
presentFence1->signalForTest(30);
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(token1, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
- presentFence2->signalForTest(60);
-
+ addEmptyDisplayFrame();
flushTrace();
tracingSession->StopBlocking();
@@ -675,11 +643,9 @@
TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) {
auto tracingSession = getTracingSessionForTest();
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
tracingSession->StartBlocking();
int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30});
- int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken({}, sPidOne, sUidOne,
sLayerNameOne, sLayerNameOne);
@@ -690,12 +656,7 @@
mFrameTimeline->setSfPresent(25, presentFence1);
presentFence1->signalForTest(30);
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
- presentFence2->signalForTest(60);
-
+ addEmptyDisplayFrame();
flushTrace();
tracingSession->StopBlocking();
@@ -705,6 +666,65 @@
EXPECT_EQ(packets.size(), 4u);
}
+ProtoExpectedDisplayFrameStart createProtoExpectedDisplayFrameStart(int64_t cookie, int64_t token,
+ pid_t pid) {
+ ProtoExpectedDisplayFrameStart proto;
+ proto.set_cookie(cookie);
+ proto.set_token(token);
+ proto.set_pid(pid);
+ return proto;
+}
+
+ProtoActualDisplayFrameStart createProtoActualDisplayFrameStart(
+ int64_t cookie, int64_t token, pid_t pid, ProtoPresentType presentType, bool onTimeFinish,
+ bool gpuComposition, ProtoJankType jankType) {
+ ProtoActualDisplayFrameStart proto;
+ proto.set_cookie(cookie);
+ proto.set_token(token);
+ proto.set_pid(pid);
+ proto.set_present_type(presentType);
+ proto.set_on_time_finish(onTimeFinish);
+ proto.set_gpu_composition(gpuComposition);
+ proto.set_jank_type(jankType);
+ return proto;
+}
+
+ProtoExpectedSurfaceFrameStart createProtoExpectedSurfaceFrameStart(int64_t cookie, int64_t token,
+ int64_t displayFrameToken,
+ pid_t pid,
+ std::string layerName) {
+ ProtoExpectedSurfaceFrameStart proto;
+ proto.set_cookie(cookie);
+ proto.set_token(token);
+ proto.set_display_frame_token(displayFrameToken);
+ proto.set_pid(pid);
+ proto.set_layer_name(layerName);
+ return proto;
+}
+
+ProtoActualSurfaceFrameStart createProtoActualSurfaceFrameStart(
+ int64_t cookie, int64_t token, int64_t displayFrameToken, pid_t pid, std::string layerName,
+ ProtoPresentType presentType, bool onTimeFinish, bool gpuComposition,
+ ProtoJankType jankType) {
+ ProtoActualSurfaceFrameStart proto;
+ proto.set_cookie(cookie);
+ proto.set_token(token);
+ proto.set_display_frame_token(displayFrameToken);
+ proto.set_pid(pid);
+ proto.set_layer_name(layerName);
+ proto.set_present_type(presentType);
+ proto.set_on_time_finish(onTimeFinish);
+ proto.set_gpu_composition(gpuComposition);
+ proto.set_jank_type(jankType);
+ return proto;
+}
+
+ProtoFrameEnd createProtoFrameEnd(int64_t cookie) {
+ ProtoFrameEnd proto;
+ proto.set_cookie(cookie);
+ return proto;
+}
+
void validateTraceEvent(const ProtoExpectedDisplayFrameStart& received,
const ProtoExpectedDisplayFrameStart& source) {
ASSERT_TRUE(received.has_cookie());
@@ -791,11 +811,9 @@
TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) {
auto tracingSession = getTracingSessionForTest();
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
- auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
tracingSession->StartBlocking();
int64_t displayFrameToken1 = mTokenManager->generateTokenForPredictions({10, 25, 30});
- int64_t displayFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
// Set up the display frame
mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, Fps::fromPeriodNsecs(11));
@@ -803,33 +821,18 @@
presentFence1->signalForTest(31);
int64_t traceCookie = snoopCurrentTraceCookie();
- ProtoExpectedDisplayFrameStart protoExpectedDisplayFrameStart;
- protoExpectedDisplayFrameStart.set_cookie(traceCookie + 1);
- protoExpectedDisplayFrameStart.set_token(displayFrameToken1);
- protoExpectedDisplayFrameStart.set_pid(kSurfaceFlingerPid);
+ auto protoExpectedDisplayFrameStart =
+ createProtoExpectedDisplayFrameStart(traceCookie + 1, displayFrameToken1,
+ kSurfaceFlingerPid);
+ auto protoExpectedDisplayFrameEnd = createProtoFrameEnd(traceCookie + 1);
+ auto protoActualDisplayFrameStart =
+ createProtoActualDisplayFrameStart(traceCookie + 2, displayFrameToken1,
+ kSurfaceFlingerPid,
+ FrameTimelineEvent::PRESENT_ON_TIME, true, false,
+ FrameTimelineEvent::JANK_NONE);
+ auto protoActualDisplayFrameEnd = createProtoFrameEnd(traceCookie + 2);
- ProtoFrameEnd protoExpectedDisplayFrameEnd;
- protoExpectedDisplayFrameEnd.set_cookie(traceCookie + 1);
-
- ProtoActualDisplayFrameStart protoActualDisplayFrameStart;
- protoActualDisplayFrameStart.set_cookie(traceCookie + 2);
- protoActualDisplayFrameStart.set_token(displayFrameToken1);
- protoActualDisplayFrameStart.set_pid(kSurfaceFlingerPid);
- protoActualDisplayFrameStart.set_present_type(
- ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
- protoActualDisplayFrameStart.set_on_time_finish(true);
- protoActualDisplayFrameStart.set_gpu_composition(false);
- protoActualDisplayFrameStart.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
-
- ProtoFrameEnd protoActualDisplayFrameEnd;
- protoActualDisplayFrameEnd.set_cookie(traceCookie + 2);
-
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
- presentFence2->signalForTest(55);
-
+ addEmptyDisplayFrame();
flushTrace();
tracingSession->StopBlocking();
@@ -881,6 +884,60 @@
validateTraceEvent(actualDisplayFrameEnd, protoActualDisplayFrameEnd);
}
+TEST_F(FrameTimelineTest, traceDisplayFrame_predictionExpiredDoesNotTraceExpectedTimeline) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ int64_t displayFrameToken1 = mTokenManager->generateTokenForPredictions({10, 25, 30});
+ // Flush the token so that it would expire
+ flushTokens(systemTime() + maxTokenRetentionTime);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, Fps::fromPeriodNsecs(11));
+ mFrameTimeline->setSfPresent(26, presentFence1);
+ presentFence1->signalForTest(31);
+
+ int64_t traceCookie = snoopCurrentTraceCookie();
+
+ auto protoActualDisplayFrameStart =
+ createProtoActualDisplayFrameStart(traceCookie + 1, displayFrameToken1,
+ kSurfaceFlingerPid,
+ FrameTimelineEvent::PRESENT_UNSPECIFIED, false,
+ false, FrameTimelineEvent::JANK_UNKNOWN);
+ auto protoActualDisplayFrameEnd = createProtoFrameEnd(traceCookie + 1);
+
+ addEmptyDisplayFrame();
+ flushTrace();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Only actual timeline packets should be in the trace
+ EXPECT_EQ(packets.size(), 2u);
+
+ // Packet - 0 : ActualDisplayFrameStart
+ const auto& packet0 = packets[0];
+ ASSERT_TRUE(packet0.has_timestamp());
+ EXPECT_EQ(packet0.timestamp(), 20u);
+ ASSERT_TRUE(packet0.has_frame_timeline_event());
+
+ const auto& event0 = packet0.frame_timeline_event();
+ ASSERT_TRUE(event0.has_actual_display_frame_start());
+ const auto& actualDisplayFrameStart = event0.actual_display_frame_start();
+ validateTraceEvent(actualDisplayFrameStart, protoActualDisplayFrameStart);
+
+ // Packet - 1 : FrameEnd (ActualDisplayFrame)
+ const auto& packet1 = packets[1];
+ ASSERT_TRUE(packet1.has_timestamp());
+ EXPECT_EQ(packet1.timestamp(), 26u);
+ ASSERT_TRUE(packet1.has_frame_timeline_event());
+
+ const auto& event1 = packet1.frame_timeline_event();
+ ASSERT_TRUE(event1.has_frame_end());
+ const auto& actualDisplayFrameEnd = event1.frame_end();
+ validateTraceEvent(actualDisplayFrameEnd, protoActualDisplayFrameEnd);
+}
+
TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) {
auto tracingSession = getTracingSessionForTest();
// Layer specific increment
@@ -891,63 +948,62 @@
tracingSession->StartBlocking();
int64_t surfaceFrameToken = mTokenManager->generateTokenForPredictions({10, 25, 40});
int64_t displayFrameToken1 = mTokenManager->generateTokenForPredictions({30, 35, 40});
- int64_t displayFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60});
auto surfaceFrame1 =
mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, sInputEventId}, sPidOne,
sUidOne, sLayerNameOne, sLayerNameOne);
- surfaceFrame1->setActualStartTime(0);
- surfaceFrame1->setActualQueueTime(15);
- surfaceFrame1->setAcquireFenceTime(20);
+ auto surfaceFrame2 =
+ mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, sInputEventId}, sPidOne,
+ sUidOne, sLayerNameOne, sLayerNameOne);
+ surfaceFrame1->setActualQueueTime(10);
+ surfaceFrame1->setDropTime(15);
+
+ surfaceFrame2->setActualQueueTime(15);
+ surfaceFrame2->setAcquireFenceTime(20);
// First 2 cookies will be used by the DisplayFrame
int64_t traceCookie = snoopCurrentTraceCookie() + 2;
- ProtoExpectedSurfaceFrameStart protoExpectedSurfaceFrameStart;
- protoExpectedSurfaceFrameStart.set_cookie(traceCookie + 1);
- protoExpectedSurfaceFrameStart.set_token(surfaceFrameToken);
- protoExpectedSurfaceFrameStart.set_display_frame_token(displayFrameToken1);
- protoExpectedSurfaceFrameStart.set_pid(sPidOne);
- protoExpectedSurfaceFrameStart.set_layer_name(sLayerNameOne);
+ auto protoDroppedSurfaceFrameExpectedStart =
+ createProtoExpectedSurfaceFrameStart(traceCookie + 1, surfaceFrameToken,
+ displayFrameToken1, sPidOne, sLayerNameOne);
+ auto protoDroppedSurfaceFrameExpectedEnd = createProtoFrameEnd(traceCookie + 1);
+ auto protoDroppedSurfaceFrameActualStart =
+ createProtoActualSurfaceFrameStart(traceCookie + 2, surfaceFrameToken,
+ displayFrameToken1, sPidOne, sLayerNameOne,
+ FrameTimelineEvent::PRESENT_DROPPED, false, false,
+ FrameTimelineEvent::JANK_NONE);
+ auto protoDroppedSurfaceFrameActualEnd = createProtoFrameEnd(traceCookie + 2);
- ProtoFrameEnd protoExpectedSurfaceFrameEnd;
- protoExpectedSurfaceFrameEnd.set_cookie(traceCookie + 1);
-
- ProtoActualSurfaceFrameStart protoActualSurfaceFrameStart;
- protoActualSurfaceFrameStart.set_cookie(traceCookie + 2);
- protoActualSurfaceFrameStart.set_token(surfaceFrameToken);
- protoActualSurfaceFrameStart.set_display_frame_token(displayFrameToken1);
- protoActualSurfaceFrameStart.set_pid(sPidOne);
- protoActualSurfaceFrameStart.set_layer_name(sLayerNameOne);
- protoActualSurfaceFrameStart.set_present_type(
- ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
- protoActualSurfaceFrameStart.set_on_time_finish(true);
- protoActualSurfaceFrameStart.set_gpu_composition(false);
- protoActualSurfaceFrameStart.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
-
- ProtoFrameEnd protoActualSurfaceFrameEnd;
- protoActualSurfaceFrameEnd.set_cookie(traceCookie + 2);
+ auto protoPresentedSurfaceFrameExpectedStart =
+ createProtoExpectedSurfaceFrameStart(traceCookie + 3, surfaceFrameToken,
+ displayFrameToken1, sPidOne, sLayerNameOne);
+ auto protoPresentedSurfaceFrameExpectedEnd = createProtoFrameEnd(traceCookie + 3);
+ auto protoPresentedSurfaceFrameActualStart =
+ createProtoActualSurfaceFrameStart(traceCookie + 4, surfaceFrameToken,
+ displayFrameToken1, sPidOne, sLayerNameOne,
+ FrameTimelineEvent::PRESENT_ON_TIME, true, false,
+ FrameTimelineEvent::JANK_NONE);
+ auto protoPresentedSurfaceFrameActualEnd = createProtoFrameEnd(traceCookie + 4);
// Set up the display frame
mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, Fps::fromPeriodNsecs(11));
- surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);
+ surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Dropped);
+ surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented);
mFrameTimeline->addSurfaceFrame(surfaceFrame1);
+ mFrameTimeline->addSurfaceFrame(surfaceFrame2);
mFrameTimeline->setSfPresent(26, presentFence1);
presentFence1->signalForTest(40);
- // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the
- // next frame
- mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, Fps::fromPeriodNsecs(11));
- mFrameTimeline->setSfPresent(55, presentFence2);
- presentFence2->signalForTest(55);
-
+ addEmptyDisplayFrame();
flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- EXPECT_EQ(packets.size(), 8u);
+ // 4 DisplayFrame + 4 DroppedSurfaceFrame + 4 PresentedSurfaceFrame
+ EXPECT_EQ(packets.size(), 12u);
- // Packet - 4 : ExpectedSurfaceFrameStart
+ // Packet - 4 : ExpectedSurfaceFrameStart1
const auto& packet4 = packets[4];
ASSERT_TRUE(packet4.has_timestamp());
EXPECT_EQ(packet4.timestamp(), 10u);
@@ -955,10 +1011,10 @@
const auto& event4 = packet4.frame_timeline_event();
ASSERT_TRUE(event4.has_expected_surface_frame_start());
- const auto& expectedSurfaceFrameStart = event4.expected_surface_frame_start();
- validateTraceEvent(expectedSurfaceFrameStart, protoExpectedSurfaceFrameStart);
+ const auto& expectedSurfaceFrameStart1 = event4.expected_surface_frame_start();
+ validateTraceEvent(expectedSurfaceFrameStart1, protoDroppedSurfaceFrameExpectedStart);
- // Packet - 5 : FrameEnd (ExpectedSurfaceFrame)
+ // Packet - 5 : FrameEnd (ExpectedSurfaceFrame1)
const auto& packet5 = packets[5];
ASSERT_TRUE(packet5.has_timestamp());
EXPECT_EQ(packet5.timestamp(), 25u);
@@ -966,10 +1022,10 @@
const auto& event5 = packet5.frame_timeline_event();
ASSERT_TRUE(event5.has_frame_end());
- const auto& expectedSurfaceFrameEnd = event5.frame_end();
- validateTraceEvent(expectedSurfaceFrameEnd, protoExpectedSurfaceFrameEnd);
+ const auto& expectedSurfaceFrameEnd1 = event5.frame_end();
+ validateTraceEvent(expectedSurfaceFrameEnd1, protoDroppedSurfaceFrameExpectedEnd);
- // Packet - 6 : ActualSurfaceFrameStart
+ // Packet - 6 : ActualSurfaceFrameStart1
const auto& packet6 = packets[6];
ASSERT_TRUE(packet6.has_timestamp());
EXPECT_EQ(packet6.timestamp(), 10u);
@@ -977,18 +1033,143 @@
const auto& event6 = packet6.frame_timeline_event();
ASSERT_TRUE(event6.has_actual_surface_frame_start());
- const auto& actualSurfaceFrameStart = event6.actual_surface_frame_start();
- validateTraceEvent(actualSurfaceFrameStart, protoActualSurfaceFrameStart);
+ const auto& actualSurfaceFrameStart1 = event6.actual_surface_frame_start();
+ validateTraceEvent(actualSurfaceFrameStart1, protoDroppedSurfaceFrameActualStart);
- // Packet - 7 : FrameEnd (ActualSurfaceFrame)
+ // Packet - 7 : FrameEnd (ActualSurfaceFrame1)
const auto& packet7 = packets[7];
ASSERT_TRUE(packet7.has_timestamp());
- EXPECT_EQ(packet7.timestamp(), 20u);
+ EXPECT_EQ(packet7.timestamp(), 15u);
ASSERT_TRUE(packet7.has_frame_timeline_event());
const auto& event7 = packet7.frame_timeline_event();
ASSERT_TRUE(event7.has_frame_end());
- const auto& actualSurfaceFrameEnd = event7.frame_end();
+ const auto& actualSurfaceFrameEnd1 = event7.frame_end();
+ validateTraceEvent(actualSurfaceFrameEnd1, protoDroppedSurfaceFrameActualEnd);
+
+ // Packet - 8 : ExpectedSurfaceFrameStart2
+ const auto& packet8 = packets[8];
+ ASSERT_TRUE(packet8.has_timestamp());
+ EXPECT_EQ(packet8.timestamp(), 10u);
+ ASSERT_TRUE(packet8.has_frame_timeline_event());
+
+ const auto& event8 = packet8.frame_timeline_event();
+ ASSERT_TRUE(event8.has_expected_surface_frame_start());
+ const auto& expectedSurfaceFrameStart2 = event8.expected_surface_frame_start();
+ validateTraceEvent(expectedSurfaceFrameStart2, protoPresentedSurfaceFrameExpectedStart);
+
+ // Packet - 9 : FrameEnd (ExpectedSurfaceFrame2)
+ const auto& packet9 = packets[9];
+ ASSERT_TRUE(packet9.has_timestamp());
+ EXPECT_EQ(packet9.timestamp(), 25u);
+ ASSERT_TRUE(packet9.has_frame_timeline_event());
+
+ const auto& event9 = packet9.frame_timeline_event();
+ ASSERT_TRUE(event9.has_frame_end());
+ const auto& expectedSurfaceFrameEnd2 = event9.frame_end();
+ validateTraceEvent(expectedSurfaceFrameEnd2, protoPresentedSurfaceFrameExpectedEnd);
+
+ // Packet - 10 : ActualSurfaceFrameStart2
+ const auto& packet10 = packets[10];
+ ASSERT_TRUE(packet10.has_timestamp());
+ EXPECT_EQ(packet10.timestamp(), 10u);
+ ASSERT_TRUE(packet10.has_frame_timeline_event());
+
+ const auto& event10 = packet10.frame_timeline_event();
+ ASSERT_TRUE(event10.has_actual_surface_frame_start());
+ const auto& actualSurfaceFrameStart2 = event10.actual_surface_frame_start();
+ validateTraceEvent(actualSurfaceFrameStart2, protoPresentedSurfaceFrameActualStart);
+
+ // Packet - 11 : FrameEnd (ActualSurfaceFrame2)
+ const auto& packet11 = packets[11];
+ ASSERT_TRUE(packet11.has_timestamp());
+ EXPECT_EQ(packet11.timestamp(), 20u);
+ ASSERT_TRUE(packet11.has_frame_timeline_event());
+
+ const auto& event11 = packet11.frame_timeline_event();
+ ASSERT_TRUE(event11.has_frame_end());
+ const auto& actualSurfaceFrameEnd2 = event11.frame_end();
+ validateTraceEvent(actualSurfaceFrameEnd2, protoPresentedSurfaceFrameActualEnd);
+}
+
+TEST_F(FrameTimelineTest, traceSurfaceFrame_predictionExpiredDoesNotTraceExpectedTimeline) {
+ auto tracingSession = getTracingSessionForTest();
+ auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
+
+ tracingSession->StartBlocking();
+ constexpr nsecs_t appStartTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count();
+ constexpr nsecs_t appEndTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count();
+ constexpr nsecs_t appPresentTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(30ms).count();
+ int64_t surfaceFrameToken =
+ mTokenManager->generateTokenForPredictions({appStartTime, appEndTime, appPresentTime});
+
+ // Flush the token so that it would expire
+ flushTokens(systemTime() + maxTokenRetentionTime);
+ auto surfaceFrame1 =
+ mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, /*inputEventId*/ 0},
+ sPidOne, sUidOne, sLayerNameOne,
+ sLayerNameOne);
+ surfaceFrame1->setActualQueueTime(appEndTime);
+ surfaceFrame1->setAcquireFenceTime(appEndTime);
+
+ constexpr nsecs_t sfStartTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count();
+ constexpr nsecs_t sfEndTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(30ms).count();
+ constexpr nsecs_t sfPresentTime =
+ std::chrono::duration_cast<std::chrono::nanoseconds>(30ms).count();
+ int64_t displayFrameToken =
+ mTokenManager->generateTokenForPredictions({sfStartTime, sfEndTime, sfPresentTime});
+
+ // First 2 cookies will be used by the DisplayFrame
+ int64_t traceCookie = snoopCurrentTraceCookie() + 2;
+
+ auto protoActualSurfaceFrameStart =
+ createProtoActualSurfaceFrameStart(traceCookie + 1, surfaceFrameToken,
+ displayFrameToken, sPidOne, sLayerNameOne,
+ FrameTimelineEvent::PRESENT_UNSPECIFIED, false,
+ false, FrameTimelineEvent::JANK_UNKNOWN);
+ auto protoActualSurfaceFrameEnd = createProtoFrameEnd(traceCookie + 1);
+
+ // Set up the display frame
+ mFrameTimeline->setSfWakeUp(displayFrameToken, sfStartTime, Fps::fromPeriodNsecs(11));
+ surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented);
+ mFrameTimeline->addSurfaceFrame(surfaceFrame1);
+ mFrameTimeline->setSfPresent(sfEndTime, presentFence1);
+ presentFence1->signalForTest(sfPresentTime);
+
+ addEmptyDisplayFrame();
+ flushTrace();
+ tracingSession->StopBlocking();
+
+ auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
+ // Display Frame 4 packets + SurfaceFrame 2 packets
+ ASSERT_EQ(packets.size(), 6u);
+
+ // Packet - 4 : ActualSurfaceFrameStart
+ const auto& packet4 = packets[4];
+ ASSERT_TRUE(packet4.has_timestamp());
+ EXPECT_EQ(packet4.timestamp(),
+ static_cast<uint64_t>(appEndTime - SurfaceFrame::kPredictionExpiredStartTimeDelta));
+ ASSERT_TRUE(packet4.has_frame_timeline_event());
+
+ const auto& event4 = packet4.frame_timeline_event();
+ ASSERT_TRUE(event4.has_actual_surface_frame_start());
+ const auto& actualSurfaceFrameStart = event4.actual_surface_frame_start();
+ validateTraceEvent(actualSurfaceFrameStart, protoActualSurfaceFrameStart);
+
+ // Packet - 5 : FrameEnd (ActualSurfaceFrame)
+ const auto& packet5 = packets[5];
+ ASSERT_TRUE(packet5.has_timestamp());
+ EXPECT_EQ(packet5.timestamp(), static_cast<uint64_t>(appEndTime));
+ ASSERT_TRUE(packet5.has_frame_timeline_event());
+
+ const auto& event5 = packet5.frame_timeline_event();
+ ASSERT_TRUE(event5.has_frame_end());
+ const auto& actualSurfaceFrameEnd = event5.frame_end();
validateTraceEvent(actualSurfaceFrameEnd, protoActualSurfaceFrameEnd);
}
diff --git a/services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp b/services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp
index aa6798d..0e5b321 100644
--- a/services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TransactionSurfaceFrameTest.cpp
@@ -157,8 +157,10 @@
sp<Fence> fence2(new Fence());
auto acquireFence2 = fenceFactory.createFenceTimeForTest(fence2);
sp<GraphicBuffer> buffer2{new GraphicBuffer(1, 1, HAL_PIXEL_FORMAT_RGBA_8888, 1, 0)};
+ nsecs_t start = systemTime();
layer->setBuffer(buffer2, fence2, 10, 20, false, mClientCache, 1, std::nullopt,
{/*vsyncId*/ 1, /*inputEventId*/ 0});
+ nsecs_t end = systemTime();
acquireFence2->signalForTest(12);
EXPECT_EQ(0u, layer->mCurrentState.bufferlessSurfaceFramesTX.size());
@@ -171,6 +173,9 @@
EXPECT_EQ(1, droppedSurfaceFrame->getToken());
EXPECT_EQ(PresentState::Dropped, droppedSurfaceFrame->getPresentState());
+ EXPECT_EQ(0u, droppedSurfaceFrame->getActuals().endTime);
+ auto dropTime = droppedSurfaceFrame->getDropTime();
+ EXPECT_TRUE(dropTime > start && dropTime < end);
EXPECT_EQ(1, presentedSurfaceFrame->getToken());
EXPECT_EQ(PresentState::Presented, presentedSurfaceFrame->getPresentState());