Send FrameTimeline packets as separate start and end messages
To avoid scoped slices, the FrameTimelineEvent proto was updated to
contain separate Start and End messages for SurfaceFrame and
DisplayFrame. This change updates the platform to send packets according
to the new proto.
Bug: 173426914
Test: libsurfaceflinger_unittest
Change-Id: I678f5b2b94109409b57d2ac61db704f77d149c76
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
index a8fef04..c994434 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -239,11 +239,16 @@
return minTime;
}
+int64_t TraceCookieCounter::getCookieForTracing() {
+ return ++mTraceCookie;
+}
+
SurfaceFrame::SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
std::string debugName, PredictionState predictionState,
frametimeline::TimelineItem&& predictions,
std::shared_ptr<TimeStats> timeStats,
- JankClassificationThresholds thresholds)
+ JankClassificationThresholds thresholds,
+ TraceCookieCounter* traceCookieCounter)
: mToken(token),
mOwnerPid(ownerPid),
mOwnerUid(ownerUid),
@@ -254,7 +259,8 @@
mPredictions(predictions),
mActuals({0, 0, 0}),
mTimeStats(timeStats),
- mJankClassificationThresholds(thresholds) {}
+ mJankClassificationThresholds(thresholds),
+ mTraceCookieCounter(*traceCookieCounter) {}
void SurfaceFrame::setActualStartTime(nsecs_t actualStartTime) {
std::lock_guard<std::mutex> lock(mMutex);
@@ -443,7 +449,7 @@
void SurfaceFrame::trace(int64_t displayFrameToken) {
using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
- FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ {
std::lock_guard<std::mutex> lock(mMutex);
if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
ALOGD("Cannot trace SurfaceFrame - %s with invalid token", mLayerName.c_str());
@@ -453,36 +459,83 @@
mLayerName.c_str());
return;
}
+ }
+
+ int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+ // Expected timeline start
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ std::lock_guard<std::mutex> lock(mMutex);
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
- packet->set_timestamp(static_cast<uint64_t>(systemTime()));
+ packet->set_timestamp(static_cast<uint64_t>(mPredictions.startTime));
auto* event = packet->set_frame_timeline_event();
- auto* surfaceFrameEvent = event->set_surface_frame();
+ auto* expectedSurfaceFrameStartEvent = event->set_expected_surface_frame_start();
- surfaceFrameEvent->set_token(mToken);
- surfaceFrameEvent->set_display_frame_token(displayFrameToken);
+ expectedSurfaceFrameStartEvent->set_cookie(expectedTimelineCookie);
+
+ expectedSurfaceFrameStartEvent->set_token(mToken);
+ expectedSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
+
+ expectedSurfaceFrameStartEvent->set_pid(mOwnerPid);
+ expectedSurfaceFrameStartEvent->set_layer_name(mDebugName);
+ });
+ // Expected timeline end
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ std::lock_guard<std::mutex> lock(mMutex);
+ auto packet = ctx.NewTracePacket();
+ packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
+ packet->set_timestamp(static_cast<uint64_t>(mPredictions.endTime));
+
+ auto* event = packet->set_frame_timeline_event();
+ auto* expectedSurfaceFrameEndEvent = event->set_frame_end();
+
+ expectedSurfaceFrameEndEvent->set_cookie(expectedTimelineCookie);
+ });
+
+ int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+ // Actual timeline start
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ std::lock_guard<std::mutex> 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));
+
+ auto* event = packet->set_frame_timeline_event();
+ auto* actualSurfaceFrameStartEvent = event->set_actual_surface_frame_start();
+
+ actualSurfaceFrameStartEvent->set_cookie(actualTimelineCookie);
+
+ actualSurfaceFrameStartEvent->set_token(mToken);
+ actualSurfaceFrameStartEvent->set_display_frame_token(displayFrameToken);
+
+ actualSurfaceFrameStartEvent->set_pid(mOwnerPid);
+ actualSurfaceFrameStartEvent->set_layer_name(mDebugName);
if (mPresentState == PresentState::Dropped) {
- surfaceFrameEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
+ actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_DROPPED);
} else if (mPresentState == PresentState::Unknown) {
- surfaceFrameEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
+ actualSurfaceFrameStartEvent->set_present_type(FrameTimelineEvent::PRESENT_UNSPECIFIED);
} else {
- surfaceFrameEvent->set_present_type(toProto(mFramePresentMetadata));
+ actualSurfaceFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
}
- surfaceFrameEvent->set_on_time_finish(mFrameReadyMetadata ==
- FrameReadyMetadata::OnTimeFinish);
- surfaceFrameEvent->set_gpu_composition(mGpuComposition);
- surfaceFrameEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
+ actualSurfaceFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
+ FrameReadyMetadata::OnTimeFinish);
+ actualSurfaceFrameStartEvent->set_gpu_composition(mGpuComposition);
+ actualSurfaceFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
+ });
+ // Actual timeline end
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ std::lock_guard<std::mutex> 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));
- surfaceFrameEvent->set_expected_start_ns(mPredictions.startTime);
- surfaceFrameEvent->set_expected_end_ns(mPredictions.endTime);
+ auto* event = packet->set_frame_timeline_event();
+ auto* actualSurfaceFrameEndEvent = event->set_frame_end();
- surfaceFrameEvent->set_actual_start_ns(mActuals.startTime);
- surfaceFrameEvent->set_actual_end_ns(mActuals.endTime);
-
- surfaceFrameEvent->set_layer_name(mDebugName);
- surfaceFrameEvent->set_pid(mOwnerPid);
+ actualSurfaceFrameEndEvent->set_cookie(actualTimelineCookie);
});
}
@@ -520,11 +573,13 @@
FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
JankClassificationThresholds thresholds)
- : mCurrentDisplayFrame(std::make_shared<DisplayFrame>(timeStats, thresholds)),
- mMaxDisplayFrames(kDefaultMaxDisplayFrames),
+ : mMaxDisplayFrames(kDefaultMaxDisplayFrames),
mTimeStats(std::move(timeStats)),
mSurfaceFlingerPid(surfaceFlingerPid),
- mJankClassificationThresholds(thresholds) {}
+ mJankClassificationThresholds(thresholds) {
+ mCurrentDisplayFrame =
+ std::make_shared<DisplayFrame>(mTimeStats, thresholds, &mTraceCookieCounter);
+}
void FrameTimeline::onBootFinished() {
perfetto::TracingInitArgs args;
@@ -547,27 +602,29 @@
return std::make_shared<SurfaceFrame>(ISurfaceComposer::INVALID_VSYNC_ID, ownerPid,
ownerUid, std::move(layerName), std::move(debugName),
PredictionState::None, TimelineItem(), mTimeStats,
- mJankClassificationThresholds);
+ mJankClassificationThresholds, &mTraceCookieCounter);
}
std::optional<TimelineItem> predictions = mTokenManager.getPredictionsForToken(*token);
if (predictions) {
return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
std::move(debugName), PredictionState::Valid,
std::move(*predictions), mTimeStats,
- mJankClassificationThresholds);
+ mJankClassificationThresholds, &mTraceCookieCounter);
}
return std::make_shared<SurfaceFrame>(*token, ownerPid, ownerUid, std::move(layerName),
std::move(debugName), PredictionState::Expired,
- TimelineItem(), mTimeStats,
- mJankClassificationThresholds);
+ TimelineItem(), mTimeStats, mJankClassificationThresholds,
+ &mTraceCookieCounter);
}
FrameTimeline::DisplayFrame::DisplayFrame(std::shared_ptr<TimeStats> timeStats,
- JankClassificationThresholds thresholds)
+ JankClassificationThresholds thresholds,
+ TraceCookieCounter* traceCookieCounter)
: mSurfaceFlingerPredictions(TimelineItem()),
mSurfaceFlingerActuals(TimelineItem()),
mTimeStats(timeStats),
- mJankClassificationThresholds(thresholds) {
+ mJankClassificationThresholds(thresholds),
+ mTraceCookieCounter(*traceCookieCounter) {
mSurfaceFrames.reserve(kNumSurfaceFramesInitial);
}
@@ -725,32 +782,69 @@
}
void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const {
+ if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
+ ALOGD("Cannot trace DisplayFrame with invalid token");
+ return;
+ }
+
+ int64_t expectedTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+ // Expected timeline start
FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
- if (mToken == ISurfaceComposer::INVALID_VSYNC_ID) {
- ALOGD("Cannot trace DisplayFrame with invalid token");
- return;
- }
auto packet = ctx.NewTracePacket();
packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
- packet->set_timestamp(static_cast<uint64_t>(systemTime()));
+ packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.startTime));
auto* event = packet->set_frame_timeline_event();
- auto* displayFrameEvent = event->set_display_frame();
+ auto* expectedDisplayFrameStartEvent = event->set_expected_display_frame_start();
- displayFrameEvent->set_token(mToken);
- displayFrameEvent->set_present_type(toProto(mFramePresentMetadata));
- displayFrameEvent->set_on_time_finish(mFrameReadyMetadata ==
- FrameReadyMetadata::OnTimeFinish);
- displayFrameEvent->set_gpu_composition(mGpuComposition);
- displayFrameEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
+ expectedDisplayFrameStartEvent->set_cookie(expectedTimelineCookie);
- displayFrameEvent->set_expected_start_ns(mSurfaceFlingerPredictions.startTime);
- displayFrameEvent->set_expected_end_ns(mSurfaceFlingerPredictions.endTime);
+ expectedDisplayFrameStartEvent->set_token(mToken);
+ 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_MONOTONIC);
+ packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerPredictions.endTime));
- displayFrameEvent->set_actual_start_ns(mSurfaceFlingerActuals.startTime);
- displayFrameEvent->set_actual_end_ns(mSurfaceFlingerActuals.endTime);
+ auto* event = packet->set_frame_timeline_event();
+ auto* expectedDisplayFrameEndEvent = event->set_frame_end();
- displayFrameEvent->set_pid(surfaceFlingerPid);
+ expectedDisplayFrameEndEvent->set_cookie(expectedTimelineCookie);
+ });
+
+ int64_t actualTimelineCookie = mTraceCookieCounter.getCookieForTracing();
+ // Expected timeline start
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ auto packet = ctx.NewTracePacket();
+ packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
+ packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.startTime));
+
+ auto* event = packet->set_frame_timeline_event();
+ auto* actualDisplayFrameStartEvent = event->set_actual_display_frame_start();
+
+ actualDisplayFrameStartEvent->set_cookie(actualTimelineCookie);
+
+ actualDisplayFrameStartEvent->set_token(mToken);
+ actualDisplayFrameStartEvent->set_pid(surfaceFlingerPid);
+
+ actualDisplayFrameStartEvent->set_present_type(toProto(mFramePresentMetadata));
+ actualDisplayFrameStartEvent->set_on_time_finish(mFrameReadyMetadata ==
+ FrameReadyMetadata::OnTimeFinish);
+ actualDisplayFrameStartEvent->set_gpu_composition(mGpuComposition);
+ actualDisplayFrameStartEvent->set_jank_type(jankTypeBitmaskToProto(mJankType));
+ });
+ // Expected timeline end
+ FrameTimelineDataSource::Trace([&](FrameTimelineDataSource::TraceContext ctx) {
+ auto packet = ctx.NewTracePacket();
+ packet->set_timestamp_clock_id(perfetto::protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
+ packet->set_timestamp(static_cast<uint64_t>(mSurfaceFlingerActuals.endTime));
+
+ auto* event = packet->set_frame_timeline_event();
+ auto* actualDisplayFrameEndEvent = event->set_frame_end();
+
+ actualDisplayFrameEndEvent->set_cookie(actualTimelineCookie);
});
for (auto& surfaceFrame : mSurfaceFrames) {
@@ -786,8 +880,8 @@
}
mDisplayFrames.push_back(mCurrentDisplayFrame);
mCurrentDisplayFrame.reset();
- mCurrentDisplayFrame =
- std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds);
+ mCurrentDisplayFrame = std::make_shared<DisplayFrame>(mTimeStats, mJankClassificationThresholds,
+ &mTraceCookieCounter);
}
nsecs_t FrameTimeline::DisplayFrame::getBaseTime() const {
diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
index f5239aa..ed38cc6 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h
@@ -127,6 +127,23 @@
None, // Predictions are either not present or didn't come from TokenManager
};
+/*
+ * Trace cookie is used to send start and end timestamps of <Surface/Display>Frames separately
+ * without needing to resend all the other information. We send all info to perfetto, along with a
+ * new cookie, in the start of a frame. For the corresponding end, we just send the same cookie.
+ * This helps in reducing the amount of data emitted by the producer.
+ */
+class TraceCookieCounter {
+public:
+ int64_t getCookieForTracing();
+
+private:
+ // Friend class for testing
+ friend class android::frametimeline::FrameTimelineTest;
+
+ std::atomic<int64_t> mTraceCookie = 0;
+};
+
class SurfaceFrame {
public:
enum class PresentState {
@@ -139,7 +156,8 @@
// TokenManager), Thresholds and TimeStats pointer.
SurfaceFrame(int64_t token, pid_t ownerPid, uid_t ownerUid, std::string layerName,
std::string debugName, PredictionState predictionState, TimelineItem&& predictions,
- std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds);
+ std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds,
+ TraceCookieCounter* traceCookieCounter);
~SurfaceFrame() = default;
// Returns std::nullopt if the frame hasn't been classified yet.
@@ -205,6 +223,9 @@
// for BufferStuffing where the current buffer is expected to be ready but the previous buffer
// was latched instead.
nsecs_t mLastLatchTime GUARDED_BY(mMutex) = 0;
+ // TraceCookieCounter is used to obtain the cookie for sendig trace packets to perfetto. Using a
+ // reference here because the counter is owned by FrameTimeline, which outlives SurfaceFrame.
+ TraceCookieCounter& mTraceCookieCounter;
};
/*
@@ -291,7 +312,8 @@
*/
class DisplayFrame {
public:
- DisplayFrame(std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds);
+ DisplayFrame(std::shared_ptr<TimeStats> timeStats, JankClassificationThresholds thresholds,
+ TraceCookieCounter* traceCookieCounter);
virtual ~DisplayFrame() = default;
// Dumpsys interface - dumps only if the DisplayFrame itself is janky or is at least one
// SurfaceFrame is janky.
@@ -360,6 +382,10 @@
// The refresh rate (vsync period) in nanoseconds as seen by SF during this DisplayFrame's
// timeline
nsecs_t mVsyncPeriod = 0;
+ // TraceCookieCounter is used to obtain the cookie for sendig trace packets to perfetto.
+ // Using a reference here because the counter is owned by FrameTimeline, which outlives
+ // DisplayFrame.
+ TraceCookieCounter& mTraceCookieCounter;
};
FrameTimeline(std::shared_ptr<TimeStats> timeStats, pid_t surfaceFlingerPid,
@@ -402,6 +428,7 @@
mPendingPresentFences GUARDED_BY(mMutex);
std::shared_ptr<DisplayFrame> mCurrentDisplayFrame GUARDED_BY(mMutex);
TokenManager mTokenManager;
+ TraceCookieCounter mTraceCookieCounter;
mutable std::mutex mMutex;
uint32_t mMaxDisplayFrames;
std::shared_ptr<TimeStats> mTimeStats;
diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
index 169698b..e2584e2 100644
--- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
+++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp
@@ -33,8 +33,13 @@
using testing::AtLeast;
using testing::Contains;
using FrameTimelineEvent = perfetto::protos::FrameTimelineEvent;
-using ProtoDisplayFrame = perfetto::protos::FrameTimelineEvent_DisplayFrame;
-using ProtoSurfaceFrame = perfetto::protos::FrameTimelineEvent_SurfaceFrame;
+using ProtoExpectedDisplayFrameStart =
+ perfetto::protos::FrameTimelineEvent_ExpectedDisplayFrameStart;
+using ProtoExpectedSurfaceFrameStart =
+ perfetto::protos::FrameTimelineEvent_ExpectedSurfaceFrameStart;
+using ProtoActualDisplayFrameStart = perfetto::protos::FrameTimelineEvent_ActualDisplayFrameStart;
+using ProtoActualSurfaceFrameStart = perfetto::protos::FrameTimelineEvent_ActualSurfaceFrameStart;
+using ProtoFrameEnd = perfetto::protos::FrameTimelineEvent_FrameEnd;
using ProtoPresentType = perfetto::protos::FrameTimelineEvent_PresentType;
using ProtoJankType = perfetto::protos::FrameTimelineEvent_JankType;
@@ -67,10 +72,11 @@
void SetUp() override {
mTimeStats = std::make_shared<mock::TimeStats>();
- mFrameTimeline = std::make_unique<impl::FrameTimeline>(mTimeStats, mSurfaceFlingerPid,
+ mFrameTimeline = std::make_unique<impl::FrameTimeline>(mTimeStats, kSurfaceFlingerPid,
kTestThresholds);
mFrameTimeline->registerDataSource();
mTokenManager = &mFrameTimeline->mTokenManager;
+ mTraceCookieCounter = &mFrameTimeline->mTraceCookieCounter;
maxDisplayFrames = &mFrameTimeline->mMaxDisplayFrames;
maxTokenRetentionTime = mTokenManager->kMaxRetentionTime;
}
@@ -130,22 +136,31 @@
a.presentTime == b.presentTime;
}
- const std::map<int64_t, TokenManagerPrediction>& getPredictions() {
+ const std::map<int64_t, TokenManagerPrediction>& getPredictions() const {
return mTokenManager->mPredictions;
}
- uint32_t getNumberOfDisplayFrames() {
+ uint32_t getNumberOfDisplayFrames() const {
std::lock_guard<std::mutex> lock(mFrameTimeline->mMutex);
return static_cast<uint32_t>(mFrameTimeline->mDisplayFrames.size());
}
+ int64_t snoopCurrentTraceCookie() const { return mTraceCookieCounter->mTraceCookie; }
+
+ void flushTrace() {
+ using FrameTimelineDataSource = impl::FrameTimeline::FrameTimelineDataSource;
+ FrameTimelineDataSource::Trace(
+ [&](FrameTimelineDataSource::TraceContext ctx) { ctx.Flush(); });
+ }
+
std::shared_ptr<mock::TimeStats> mTimeStats;
std::unique_ptr<impl::FrameTimeline> mFrameTimeline;
impl::TokenManager* mTokenManager;
+ TraceCookieCounter* mTraceCookieCounter;
FenceToFenceTimeMap fenceFactory;
uint32_t* maxDisplayFrames;
nsecs_t maxTokenRetentionTime;
- pid_t mSurfaceFlingerPid = 666;
+ static constexpr pid_t kSurfaceFlingerPid = 666;
static constexpr nsecs_t kPresentThreshold =
std::chrono::duration_cast<std::chrono::nanoseconds>(2ns).count();
static constexpr nsecs_t kDeadlineThreshold =
@@ -549,7 +564,7 @@
TEST_F(FrameTimelineTest, tracing_sanityTest) {
auto tracingSession = getTracingSessionForTest();
// Global increment
- EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2);
+ EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_));
// Layer specific increment
EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
@@ -574,23 +589,18 @@
mFrameTimeline->setSfPresent(55, presentFence2);
presentFence2->signalForTest(55);
- // The SurfaceFrame packet from the first frame is emitted, but not flushed yet. Emitting a new
- // packet will flush it. To emit a new packet, we'll need to call flushPendingPresentFences()
- // again, which is done by setSfPresent().
- addEmptyDisplayFrame();
+ flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- // Display Frame 1 has two packets - DisplayFrame and a SurfaceFrame.
- // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
- // flushed through traced, so this is not counted.
- EXPECT_EQ(packets.size(), 2);
+ // Display Frame 1 has 8 packets - 4 from DisplayFrame and 4 from SurfaceFrame.
+ EXPECT_EQ(packets.size(), 8);
}
TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) {
auto tracingSession = getTracingSessionForTest();
// Global increment
- EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2);
+ EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
@@ -608,20 +618,17 @@
mFrameTimeline->setSfPresent(55, presentFence2);
presentFence2->signalForTest(60);
- addEmptyDisplayFrame();
+ flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- // Display Frame 1 has no packets.
- // Display Frame 2 has one packet - DisplayFrame. However, this packet has
- // been emitted but not flushed through traced, so this is not counted.
EXPECT_EQ(packets.size(), 0);
}
TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) {
auto tracingSession = getTracingSessionForTest();
// Global increment
- EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2);
+ EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
@@ -644,21 +651,38 @@
mFrameTimeline->setSfPresent(55, presentFence2);
presentFence2->signalForTest(60);
- addEmptyDisplayFrame();
+ flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- // Display Frame 1 has one packet - DisplayFrame (SurfaceFrame shouldn't be traced since it has
- // an invalid token).
- // Display Frame 2 has one packet - DisplayFrame. However, this packet has
- // been emitted but not flushed through traced, so this is not counted.
- EXPECT_EQ(packets.size(), 1);
+ // Display Frame 1 has 4 packets (SurfaceFrame shouldn't be traced since it has an invalid
+ // token).
+ EXPECT_EQ(packets.size(), 4);
}
-void validateDisplayFrameEvent(const ProtoDisplayFrame& received, const ProtoDisplayFrame& source) {
+void validateTraceEvent(const ProtoExpectedDisplayFrameStart& received,
+ const ProtoExpectedDisplayFrameStart& source) {
+ ASSERT_TRUE(received.has_cookie());
+ EXPECT_EQ(received.cookie(), source.cookie());
+
ASSERT_TRUE(received.has_token());
EXPECT_EQ(received.token(), source.token());
+ ASSERT_TRUE(received.has_pid());
+ EXPECT_EQ(received.pid(), source.pid());
+}
+
+void validateTraceEvent(const ProtoActualDisplayFrameStart& received,
+ const ProtoActualDisplayFrameStart& source) {
+ ASSERT_TRUE(received.has_cookie());
+ EXPECT_EQ(received.cookie(), source.cookie());
+
+ ASSERT_TRUE(received.has_token());
+ EXPECT_EQ(received.token(), source.token());
+
+ ASSERT_TRUE(received.has_pid());
+ EXPECT_EQ(received.pid(), source.pid());
+
ASSERT_TRUE(received.has_present_type());
EXPECT_EQ(received.present_type(), source.present_type());
ASSERT_TRUE(received.has_on_time_finish());
@@ -667,25 +691,43 @@
EXPECT_EQ(received.gpu_composition(), source.gpu_composition());
ASSERT_TRUE(received.has_jank_type());
EXPECT_EQ(received.jank_type(), source.jank_type());
-
- ASSERT_TRUE(received.has_expected_start_ns());
- EXPECT_EQ(received.expected_start_ns(), source.expected_start_ns());
- ASSERT_TRUE(received.has_expected_end_ns());
- EXPECT_EQ(received.expected_end_ns(), source.expected_end_ns());
-
- ASSERT_TRUE(received.has_actual_start_ns());
- EXPECT_EQ(received.actual_start_ns(), source.actual_start_ns());
- ASSERT_TRUE(received.has_actual_end_ns());
- EXPECT_EQ(received.actual_end_ns(), source.actual_end_ns());
}
-void validateSurfaceFrameEvent(const ProtoSurfaceFrame& received, const ProtoSurfaceFrame& source) {
+void validateTraceEvent(const ProtoExpectedSurfaceFrameStart& received,
+ const ProtoExpectedSurfaceFrameStart& source) {
+ ASSERT_TRUE(received.has_cookie());
+ EXPECT_EQ(received.cookie(), source.cookie());
+
ASSERT_TRUE(received.has_token());
EXPECT_EQ(received.token(), source.token());
ASSERT_TRUE(received.has_display_frame_token());
EXPECT_EQ(received.display_frame_token(), source.display_frame_token());
+ ASSERT_TRUE(received.has_pid());
+ EXPECT_EQ(received.pid(), source.pid());
+
+ ASSERT_TRUE(received.has_layer_name());
+ EXPECT_EQ(received.layer_name(), source.layer_name());
+}
+
+void validateTraceEvent(const ProtoActualSurfaceFrameStart& received,
+ const ProtoActualSurfaceFrameStart& source) {
+ ASSERT_TRUE(received.has_cookie());
+ EXPECT_EQ(received.cookie(), source.cookie());
+
+ ASSERT_TRUE(received.has_token());
+ EXPECT_EQ(received.token(), source.token());
+
+ ASSERT_TRUE(received.has_display_frame_token());
+ EXPECT_EQ(received.display_frame_token(), source.display_frame_token());
+
+ ASSERT_TRUE(received.has_pid());
+ EXPECT_EQ(received.pid(), source.pid());
+
+ ASSERT_TRUE(received.has_layer_name());
+ EXPECT_EQ(received.layer_name(), source.layer_name());
+
ASSERT_TRUE(received.has_present_type());
EXPECT_EQ(received.present_type(), source.present_type());
ASSERT_TRUE(received.has_on_time_finish());
@@ -694,27 +736,17 @@
EXPECT_EQ(received.gpu_composition(), source.gpu_composition());
ASSERT_TRUE(received.has_jank_type());
EXPECT_EQ(received.jank_type(), source.jank_type());
+}
- ASSERT_TRUE(received.has_expected_start_ns());
- EXPECT_EQ(received.expected_start_ns(), source.expected_start_ns());
- ASSERT_TRUE(received.has_expected_end_ns());
- EXPECT_EQ(received.expected_end_ns(), source.expected_end_ns());
-
- ASSERT_TRUE(received.has_actual_start_ns());
- EXPECT_EQ(received.actual_start_ns(), source.actual_start_ns());
- ASSERT_TRUE(received.has_actual_end_ns());
- EXPECT_EQ(received.actual_end_ns(), source.actual_end_ns());
-
- ASSERT_TRUE(received.has_layer_name());
- EXPECT_EQ(received.layer_name(), source.layer_name());
- ASSERT_TRUE(received.has_pid());
- EXPECT_EQ(received.pid(), source.pid());
+void validateTraceEvent(const ProtoFrameEnd& received, const ProtoFrameEnd& source) {
+ ASSERT_TRUE(received.has_cookie());
+ EXPECT_EQ(received.cookie(), source.cookie());
}
TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) {
auto tracingSession = getTracingSessionForTest();
// Global increment
- EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2);
+ EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
@@ -727,16 +759,27 @@
mFrameTimeline->setSfPresent(26, presentFence1);
presentFence1->signalForTest(31);
- ProtoDisplayFrame protoDisplayFrame;
- protoDisplayFrame.set_token(displayFrameToken1);
- protoDisplayFrame.set_present_type(ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
- protoDisplayFrame.set_on_time_finish(true);
- protoDisplayFrame.set_gpu_composition(false);
- protoDisplayFrame.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
- protoDisplayFrame.set_expected_start_ns(10);
- protoDisplayFrame.set_expected_end_ns(25);
- protoDisplayFrame.set_actual_start_ns(20);
- protoDisplayFrame.set_actual_end_ns(26);
+ int64_t traceCookie = snoopCurrentTraceCookie();
+ ProtoExpectedDisplayFrameStart protoExpectedDisplayFrameStart;
+ protoExpectedDisplayFrameStart.set_cookie(traceCookie + 1);
+ protoExpectedDisplayFrameStart.set_token(displayFrameToken1);
+ protoExpectedDisplayFrameStart.set_pid(kSurfaceFlingerPid);
+
+ 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
@@ -744,30 +787,61 @@
mFrameTimeline->setSfPresent(55, presentFence2);
presentFence2->signalForTest(55);
- addEmptyDisplayFrame();
+ flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- // Display Frame 1 has one packet - DisplayFrame.
- // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
- // flushed through traced, so this is not counted.
- EXPECT_EQ(packets.size(), 1);
+ EXPECT_EQ(packets.size(), 4);
- const auto& packet = packets[0];
- ASSERT_TRUE(packet.has_timestamp());
- ASSERT_TRUE(packet.has_frame_timeline_event());
+ // Packet - 0 : ExpectedDisplayFrameStart
+ const auto& packet0 = packets[0];
+ ASSERT_TRUE(packet0.has_timestamp());
+ EXPECT_EQ(packet0.timestamp(), 10);
+ ASSERT_TRUE(packet0.has_frame_timeline_event());
- const auto& event = packet.frame_timeline_event();
- ASSERT_TRUE(event.has_display_frame());
- ASSERT_FALSE(event.has_surface_frame());
- const auto& displayFrameEvent = event.display_frame();
- validateDisplayFrameEvent(displayFrameEvent, protoDisplayFrame);
+ const auto& event0 = packet0.frame_timeline_event();
+ ASSERT_TRUE(event0.has_expected_display_frame_start());
+ const auto& expectedDisplayFrameStart = event0.expected_display_frame_start();
+ validateTraceEvent(expectedDisplayFrameStart, protoExpectedDisplayFrameStart);
+
+ // Packet - 1 : FrameEnd (ExpectedDisplayFrame)
+ const auto& packet1 = packets[1];
+ ASSERT_TRUE(packet1.has_timestamp());
+ EXPECT_EQ(packet1.timestamp(), 25);
+ ASSERT_TRUE(packet1.has_frame_timeline_event());
+
+ const auto& event1 = packet1.frame_timeline_event();
+ ASSERT_TRUE(event1.has_frame_end());
+ const auto& expectedDisplayFrameEnd = event1.frame_end();
+ validateTraceEvent(expectedDisplayFrameEnd, protoExpectedDisplayFrameEnd);
+
+ // Packet - 2 : ActualDisplayFrameStart
+ const auto& packet2 = packets[2];
+ ASSERT_TRUE(packet2.has_timestamp());
+ EXPECT_EQ(packet2.timestamp(), 20);
+ ASSERT_TRUE(packet2.has_frame_timeline_event());
+
+ const auto& event2 = packet2.frame_timeline_event();
+ ASSERT_TRUE(event2.has_actual_display_frame_start());
+ const auto& actualDisplayFrameStart = event2.actual_display_frame_start();
+ validateTraceEvent(actualDisplayFrameStart, protoActualDisplayFrameStart);
+
+ // Packet - 3 : FrameEnd (ActualDisplayFrame)
+ const auto& packet3 = packets[3];
+ ASSERT_TRUE(packet3.has_timestamp());
+ EXPECT_EQ(packet3.timestamp(), 26);
+ ASSERT_TRUE(packet3.has_frame_timeline_event());
+
+ const auto& event3 = packet3.frame_timeline_event();
+ ASSERT_TRUE(event3.has_frame_end());
+ const auto& actualDisplayFrameEnd = event3.frame_end();
+ validateTraceEvent(actualDisplayFrameEnd, protoActualDisplayFrameEnd);
}
TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) {
auto tracingSession = getTracingSessionForTest();
// Global increment
- EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2);
+ EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_));
// Layer specific increment
EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_));
auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE);
@@ -785,19 +859,33 @@
surfaceFrame1->setActualQueueTime(15);
surfaceFrame1->setAcquireFenceTime(20);
- ProtoSurfaceFrame protoSurfaceFrame;
- protoSurfaceFrame.set_token(surfaceFrameToken);
- protoSurfaceFrame.set_display_frame_token(displayFrameToken1);
- protoSurfaceFrame.set_present_type(ProtoPresentType(FrameTimelineEvent::PRESENT_ON_TIME));
- protoSurfaceFrame.set_on_time_finish(true);
- protoSurfaceFrame.set_gpu_composition(false);
- protoSurfaceFrame.set_jank_type(ProtoJankType(FrameTimelineEvent::JANK_NONE));
- protoSurfaceFrame.set_expected_start_ns(10);
- protoSurfaceFrame.set_expected_end_ns(25);
- protoSurfaceFrame.set_actual_start_ns(0);
- protoSurfaceFrame.set_actual_end_ns(20);
- protoSurfaceFrame.set_layer_name(sLayerNameOne);
- protoSurfaceFrame.set_pid(sPidOne);
+ // 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);
+
+ 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);
// Set up the display frame
mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, 11);
@@ -812,24 +900,55 @@
mFrameTimeline->setSfPresent(55, presentFence2);
presentFence2->signalForTest(55);
- addEmptyDisplayFrame();
+ flushTrace();
tracingSession->StopBlocking();
auto packets = readFrameTimelinePacketsBlocking(tracingSession.get());
- // Display Frame 1 has one packet - DisplayFrame and a SurfaceFrame.
- // Display Frame 2 has one packet - DisplayFrame. However, this packet has been emitted but not
- // flushed through traced, so this is not counted.
- EXPECT_EQ(packets.size(), 2);
+ EXPECT_EQ(packets.size(), 8);
- const auto& packet = packets[1];
- ASSERT_TRUE(packet.has_timestamp());
- ASSERT_TRUE(packet.has_frame_timeline_event());
+ // Packet - 4 : ExpectedSurfaceFrameStart
+ const auto& packet4 = packets[4];
+ ASSERT_TRUE(packet4.has_timestamp());
+ EXPECT_EQ(packet4.timestamp(), 10);
+ ASSERT_TRUE(packet4.has_frame_timeline_event());
- const auto& event = packet.frame_timeline_event();
- ASSERT_TRUE(!event.has_display_frame());
- ASSERT_TRUE(event.has_surface_frame());
- const auto& surfaceFrameEvent = event.surface_frame();
- validateSurfaceFrameEvent(surfaceFrameEvent, protoSurfaceFrame);
+ 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);
+
+ // Packet - 5 : FrameEnd (ExpectedSurfaceFrame)
+ const auto& packet5 = packets[5];
+ ASSERT_TRUE(packet5.has_timestamp());
+ EXPECT_EQ(packet5.timestamp(), 25);
+ ASSERT_TRUE(packet5.has_frame_timeline_event());
+
+ const auto& event5 = packet5.frame_timeline_event();
+ ASSERT_TRUE(event5.has_frame_end());
+ const auto& expectedSurfaceFrameEnd = event5.frame_end();
+ validateTraceEvent(expectedSurfaceFrameEnd, protoExpectedSurfaceFrameEnd);
+
+ // Packet - 6 : ActualSurfaceFrameStart
+ const auto& packet6 = packets[6];
+ ASSERT_TRUE(packet6.has_timestamp());
+ EXPECT_EQ(packet6.timestamp(), 10);
+ ASSERT_TRUE(packet6.has_frame_timeline_event());
+
+ 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);
+
+ // Packet - 7 : FrameEnd (ActualSurfaceFrame)
+ const auto& packet7 = packets[7];
+ ASSERT_TRUE(packet7.has_timestamp());
+ EXPECT_EQ(packet7.timestamp(), 20);
+ 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();
+ validateTraceEvent(actualSurfaceFrameEnd, protoActualSurfaceFrameEnd);
}
// Tests for Jank classification