diff options
5 files changed, 239 insertions, 148 deletions
diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp index b93f30ebbf..100354adac 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.cpp +++ b/services/surfaceflinger/TimeStats/TimeStats.cpp @@ -140,11 +140,12 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventLi globalSlice.second.jankPayload.totalSFUnattributed); mStatsDelegate->statsEventWriteInt32(event, globalSlice.second.jankPayload.totalAppUnattributed); - - // TODO: populate these with real values - mStatsDelegate->statsEventWriteInt32(event, 0); // total_janky_frames_sf_scheduling - mStatsDelegate->statsEventWriteInt32(event, 0); // total_jank_frames_sf_prediction_error - mStatsDelegate->statsEventWriteInt32(event, 0); // total_jank_frames_app_buffer_stuffing + mStatsDelegate->statsEventWriteInt32(event, + globalSlice.second.jankPayload.totalSFScheduling); + mStatsDelegate->statsEventWriteInt32(event, + globalSlice.second.jankPayload.totalSFPredictionError); + mStatsDelegate->statsEventWriteInt32(event, + globalSlice.second.jankPayload.totalAppBufferStuffing); mStatsDelegate->statsEventWriteInt32(event, globalSlice.first.displayRefreshRateBucket); std::string sfDeadlineMissedBytes = histogramToProtoByteString(globalSlice.second.displayDeadlineDeltas.hist, @@ -222,11 +223,9 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFLongGpu); mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFUnattributed); mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalAppUnattributed); - - // TODO: populate these with real values - mStatsDelegate->statsEventWriteInt32(event, 0); // total_janky_frames_sf_scheduling - mStatsDelegate->statsEventWriteInt32(event, 0); // total_jank_frames_sf_prediction_error - mStatsDelegate->statsEventWriteInt32(event, 0); // total_jank_frames_app_buffer_stuffing + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFScheduling); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFPredictionError); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalAppBufferStuffing); mStatsDelegate->statsEventWriteInt32( event, layer->displayRefreshRateBucket); // display_refresh_rate_bucket mStatsDelegate->statsEventWriteInt32(event, layer->renderRateBucket); // render_rate_bucket @@ -772,9 +771,10 @@ void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate); } -static const constexpr int32_t kValidJankyReason = JankType::SurfaceFlingerCpuDeadlineMissed | - JankType::SurfaceFlingerGpuDeadlineMissed | JankType::AppDeadlineMissed | - JankType::DisplayHAL; +static const constexpr int32_t kValidJankyReason = JankType::DisplayHAL | + JankType::SurfaceFlingerCpuDeadlineMissed | JankType::SurfaceFlingerGpuDeadlineMissed | + JankType::AppDeadlineMissed | JankType::PredictionError | + JankType::SurfaceFlingerScheduling | JankType::BufferStuffing; template <class T> static void updateJankPayload(T& t, int32_t reasons) { @@ -794,6 +794,15 @@ static void updateJankPayload(T& t, int32_t reasons) { if ((reasons & JankType::AppDeadlineMissed) != 0) { t.jankPayload.totalAppUnattributed++; } + if ((reasons & JankType::PredictionError) != 0) { + t.jankPayload.totalSFPredictionError++; + } + if ((reasons & JankType::SurfaceFlingerScheduling) != 0) { + t.jankPayload.totalSFScheduling++; + } + if ((reasons & JankType::BufferStuffing) != 0) { + t.jankPayload.totalAppBufferStuffing++; + } } } diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp index 814f046c3b..d116b02d11 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp +++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp @@ -83,8 +83,11 @@ std::string TimeStatsHelper::JankPayload::toString() const { StringAppendF(&result, "jankyFrames = %d\n", totalJankyFrames); StringAppendF(&result, "sfLongCpuJankyFrames = %d\n", totalSFLongCpu); StringAppendF(&result, "sfLongGpuJankyFrames = %d\n", totalSFLongGpu); - StringAppendF(&result, "sfUnattributedJankyFrame = %d\n", totalSFUnattributed); - StringAppendF(&result, "appUnattributedJankyFrame = %d\n", totalAppUnattributed); + StringAppendF(&result, "sfUnattributedJankyFrames = %d\n", totalSFUnattributed); + StringAppendF(&result, "appUnattributedJankyFrames = %d\n", totalAppUnattributed); + StringAppendF(&result, "sfSchedulingJankyFrames = %d\n", totalSFScheduling); + StringAppendF(&result, "sfPredictionErrorJankyFrames = %d\n", totalSFPredictionError); + StringAppendF(&result, "appBufferStuffingJankyFrames = %d\n", totalAppBufferStuffing); return result; } diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h index 38ee8882a6..4556badf7b 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h +++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h @@ -48,6 +48,9 @@ public: int32_t totalSFLongGpu = 0; int32_t totalSFUnattributed = 0; int32_t totalAppUnattributed = 0; + int32_t totalSFScheduling = 0; + int32_t totalSFPredictionError = 0; + int32_t totalAppBufferStuffing = 0; std::string toString() const; }; diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp index 1c57e4c733..b8c1607562 100644 --- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp +++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp @@ -156,12 +156,9 @@ public: uint32_t* maxDisplayFrames; nsecs_t maxTokenRetentionTime; 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 = - std::chrono::duration_cast<std::chrono::nanoseconds>(2ns).count(); - static constexpr nsecs_t kStartThreshold = - std::chrono::duration_cast<std::chrono::nanoseconds>(2ns).count(); + static constexpr nsecs_t kPresentThreshold = std::chrono::nanoseconds(2ns).count(); + static constexpr nsecs_t kDeadlineThreshold = std::chrono::nanoseconds(2ns).count(); + static constexpr nsecs_t kStartThreshold = std::chrono::nanoseconds(2ns).count(); static constexpr JankClassificationThresholds kTestThresholds{kPresentThreshold, kDeadlineThreshold, kStartThreshold}; @@ -430,28 +427,21 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) { 0})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(10ms).count(), std::chrono::nanoseconds(20ms).count(), + std::chrono::nanoseconds(60ms).count()}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(52ms).count(), std::chrono::nanoseconds(56ms).count(), + std::chrono::nanoseconds(60ms).count()}); auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken1, - std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - refreshRate); - surfaceFrame1->setAcquireFenceTime( - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(20ms).count()); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); - presentFence1->signalForTest( - std::chrono::duration_cast<std::chrono::nanoseconds>(70ms).count()); + presentFence1->signalForTest(std::chrono::nanoseconds(70ms).count()); - mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(59ms).count(), - presentFence1); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(59ms).count(), presentFence1); } TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { @@ -463,27 +453,20 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(10ms).count(), std::chrono::nanoseconds(20ms).count(), + std::chrono::nanoseconds(60ms).count()}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(52ms).count(), std::chrono::nanoseconds(56ms).count(), + std::chrono::nanoseconds(60ms).count()}); auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken1, - std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - refreshRate); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); - surfaceFrame1->setAcquireFenceTime( - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count()); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(20ms).count()); mFrameTimeline->addSurfaceFrame(surfaceFrame1); - presentFence1->signalForTest( - std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); - mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), - presentFence1); + presentFence1->signalForTest(std::chrono::nanoseconds(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(56ms).count(), presentFence1); EXPECT_EQ(surfaceFrame1->getJankType(), JankType::DisplayHAL); } @@ -498,32 +481,120 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { .count()})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(10ms).count(), std::chrono::nanoseconds(20ms).count(), + std::chrono::nanoseconds(60ms).count()}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(82ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(86ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()}); + {std::chrono::nanoseconds(82ms).count(), std::chrono::nanoseconds(86ms).count(), + std::chrono::nanoseconds(90ms).count()}); auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - surfaceFrame1->setAcquireFenceTime( - std::chrono::duration_cast<std::chrono::nanoseconds>(45ms).count()); - mFrameTimeline->setSfWakeUp(sfToken1, - std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - refreshRate); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(45ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); - presentFence1->signalForTest( - std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); - mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(86ms).count(), - presentFence1); + presentFence1->signalForTest(std::chrono::nanoseconds(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(86ms).count(), presentFence1); EXPECT_EQ(surfaceFrame1->getJankType(), JankType::AppDeadlineMissed); } +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsSfScheduling) { + Fps refreshRate = Fps::fromPeriodNsecs(std::chrono::nanoseconds(32ms).count()); + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, + JankType::SurfaceFlingerScheduling, 0, 0, + std::chrono::duration_cast< + std::chrono::nanoseconds>(-10ms) + .count()})); + auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); + int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(40ms).count(), std::chrono::nanoseconds(60ms).count(), + std::chrono::nanoseconds(92ms).count()}); + int64_t sfToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(52ms).count(), std::chrono::nanoseconds(56ms).count(), + std::chrono::nanoseconds(60ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, + sUidOne, sLayerNameOne, sLayerNameOne); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(50ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); + + surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); + mFrameTimeline->addSurfaceFrame(surfaceFrame1); + presentFence1->signalForTest(std::chrono::nanoseconds(60ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(56ms).count(), presentFence1); + + EXPECT_EQ(surfaceFrame1->getJankType(), JankType::SurfaceFlingerScheduling); +} + +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsSfPredictionError) { + Fps refreshRate = Fps(16.66f); + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, JankType::PredictionError, 0, + std::chrono::duration_cast< + std::chrono::nanoseconds>(5ms) + .count(), + 0})); + auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); + int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(30ms).count(), std::chrono::nanoseconds(40ms).count(), + std::chrono::nanoseconds(60ms).count()}); + int64_t sfToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(52ms).count(), std::chrono::nanoseconds(56ms).count(), + std::chrono::nanoseconds(60ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, + sUidOne, sLayerNameOne, sLayerNameOne); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(40ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); + + surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); + mFrameTimeline->addSurfaceFrame(surfaceFrame1); + presentFence1->signalForTest(std::chrono::nanoseconds(65ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(56ms).count(), presentFence1); + + EXPECT_EQ(surfaceFrame1->getJankType(), JankType::PredictionError); +} + +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppBufferStuffing) { + Fps refreshRate = Fps::fromPeriodNsecs(std::chrono::nanoseconds(32ms).count()); + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, + JankType::BufferStuffing | + JankType::SurfaceFlingerScheduling, + 0, 0, 0})); + auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); + int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(30ms).count(), std::chrono::nanoseconds(40ms).count(), + std::chrono::nanoseconds(58ms).count()}); + int64_t sfToken1 = mTokenManager->generateTokenForPredictions( + {std::chrono::nanoseconds(82ms).count(), std::chrono::nanoseconds(86ms).count(), + std::chrono::nanoseconds(90ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, + sUidOne, sLayerNameOne, sLayerNameOne); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(40ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(82ms).count(), refreshRate); + + surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented, + /*previousLatchTime*/ + std::chrono::nanoseconds(56ms).count()); + mFrameTimeline->addSurfaceFrame(surfaceFrame1); + presentFence1->signalForTest(std::chrono::nanoseconds(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(86ms).count(), presentFence1); + + EXPECT_EQ(surfaceFrame1->getJankType(), + JankType::BufferStuffing | JankType::SurfaceFlingerScheduling); +} + TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMissWithRenderRate) { Fps refreshRate = Fps(11.0); Fps renderRate = Fps(30.0); @@ -536,29 +607,22 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMissWithRenderRate) { .count()})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + {std::chrono::nanoseconds(10ms).count(), std::chrono::nanoseconds(20ms).count(), + std::chrono::nanoseconds(60ms).count()}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions( - {std::chrono::duration_cast<std::chrono::nanoseconds>(82ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(86ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()}); + {std::chrono::nanoseconds(82ms).count(), std::chrono::nanoseconds(86ms).count(), + std::chrono::nanoseconds(90ms).count()}); auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - surfaceFrame1->setAcquireFenceTime( - std::chrono::duration_cast<std::chrono::nanoseconds>(45ms).count()); - mFrameTimeline->setSfWakeUp(sfToken1, - std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - refreshRate); + surfaceFrame1->setAcquireFenceTime(std::chrono::nanoseconds(45ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::nanoseconds(52ms).count(), refreshRate); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); surfaceFrame1->setRenderRate(renderRate); mFrameTimeline->addSurfaceFrame(surfaceFrame1); - presentFence1->signalForTest( - std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); - mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(86ms).count(), - presentFence1); + presentFence1->signalForTest(std::chrono::nanoseconds(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::nanoseconds(86ms).count(), presentFence1); EXPECT_EQ(surfaceFrame1->getJankType(), JankType::AppDeadlineMissed); } diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp index 35c32ec033..e90366448c 100644 --- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp +++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp @@ -375,6 +375,13 @@ TEST_F(TimeStatsTest, canIncreaseJankyFramesForLayer) { mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::AppDeadlineMissed, 1, 2, 3}); mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerScheduling, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::PredictionError, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::AppDeadlineMissed | JankType::BufferStuffing, 1, 2, + 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::None, 1, 2, 3}); const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); @@ -383,17 +390,23 @@ TEST_F(TimeStatsTest, canIncreaseJankyFramesForLayer) { EXPECT_THAT(result, HasSubstr(expectedResult)); expectedResult = "renderRate = " + std::to_string(RENDER_RATE_BUCKET_0) + " fps"; EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "totalTimelineFrames = " + std::to_string(5); + expectedResult = "totalTimelineFrames = " + std::to_string(8); EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "jankyFrames = " + std::to_string(4); + expectedResult = "jankyFrames = " + std::to_string(7); EXPECT_THAT(result, HasSubstr(expectedResult)); expectedResult = "sfLongCpuJankyFrames = " + std::to_string(1); EXPECT_THAT(result, HasSubstr(expectedResult)); expectedResult = "sfLongGpuJankyFrames = " + std::to_string(1); EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "sfUnattributedJankyFrame = " + std::to_string(1); + expectedResult = "sfUnattributedJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "appUnattributedJankyFrames = " + std::to_string(2); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfSchedulingJankyFrames = " + std::to_string(1); EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "appUnattributedJankyFrame = " + std::to_string(1); + expectedResult = "sfPredictionErrorJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "appBufferStuffingJankyFrames = " + std::to_string(1); EXPECT_THAT(result, HasSubstr(expectedResult)); } @@ -445,14 +458,10 @@ TEST_F(TimeStatsTest, canIncreaseCompositionStrategyChanges) { TEST_F(TimeStatsTest, canAverageFrameDuration) { EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); mTimeStats->setPowerMode(PowerMode::ON); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(16ms) - .count()); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(1ms).count(), + std::chrono::nanoseconds(6ms).count()); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(1ms).count(), + std::chrono::nanoseconds(16ms).count()); const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); EXPECT_THAT(result, HasSubstr("averageFrameDuration = 10.000 ms")); @@ -460,22 +469,19 @@ TEST_F(TimeStatsTest, canAverageFrameDuration) { TEST_F(TimeStatsTest, canAverageRenderEngineTimings) { EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms) - .count(), + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(1ms).count(), std::make_shared<FenceTime>( std::chrono::duration_cast< std::chrono::nanoseconds>(3ms) .count())); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms) - .count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(8ms) - .count()); + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(4ms).count(), + std::chrono::nanoseconds(8ms).count()); // Push a fake present fence to trigger flushing the RenderEngine timings. mTimeStats->setPowerMode(PowerMode::ON); - mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>( - std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count())); + mTimeStats->setPresentFenceGlobal( + std::make_shared<FenceTime>(std::chrono::nanoseconds(1ms).count())); const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); EXPECT_THAT(result, HasSubstr("averageRenderEngineTiming = 3.000 ms")); @@ -514,15 +520,11 @@ TEST_F(TimeStatsTest, canInsertGlobalFrameDuration) { EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); mTimeStats->setPowerMode(PowerMode::OFF); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(5ms) - .count()); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(1ms).count(), + std::chrono::nanoseconds(5ms).count()); mTimeStats->setPowerMode(PowerMode::ON); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(3ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(3ms).count(), + std::chrono::nanoseconds(6ms).count()); SFTimeStatsGlobalProto globalProto; ASSERT_TRUE(globalProto.ParseFromString(inputCommand(InputCommand::DUMP_ALL, FMT_PROTO))); @@ -536,17 +538,14 @@ TEST_F(TimeStatsTest, canInsertGlobalFrameDuration) { TEST_F(TimeStatsTest, canInsertGlobalRenderEngineTiming) { EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms) - .count(), + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(1ms).count(), std::make_shared<FenceTime>( std::chrono::duration_cast< std::chrono::nanoseconds>(3ms) .count())); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms) - .count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(4ms).count(), + std::chrono::nanoseconds(6ms).count()); // First verify that flushing RenderEngine durations did not occur yet. SFTimeStatsGlobalProto preFlushProto; @@ -555,8 +554,8 @@ TEST_F(TimeStatsTest, canInsertGlobalRenderEngineTiming) { // Push a fake present fence to trigger flushing the RenderEngine timings. mTimeStats->setPowerMode(PowerMode::ON); - mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>( - std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count())); + mTimeStats->setPresentFenceGlobal( + std::make_shared<FenceTime>(std::chrono::nanoseconds(1ms).count())); // Now we can verify that RenderEngine durations were flushed now. SFTimeStatsGlobalProto postFlushProto; @@ -791,14 +790,10 @@ TEST_F(TimeStatsTest, canClearTimeStats) { ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementClientCompositionFrames()); ASSERT_NO_FATAL_FAILURE(mTimeStats->setPowerMode(PowerMode::ON)); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(3ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms) - .count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(3ms).count(), + std::chrono::nanoseconds(6ms).count()); + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(4ms).count(), + std::chrono::nanoseconds(6ms).count()); ASSERT_NO_FATAL_FAILURE( mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(1000000))); ASSERT_NO_FATAL_FAILURE( @@ -827,16 +822,12 @@ TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) { ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementRefreshRateSwitches()); ASSERT_NO_FATAL_FAILURE(mTimeStats->incrementCompositionStrategyChanges()); mTimeStats->setPowerMode(PowerMode::ON); - mTimeStats - ->recordFrameDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(5ms) - .count()); - mTimeStats->recordRenderEngineDuration(std::chrono::duration_cast<std::chrono::nanoseconds>(4ms) - .count(), - std::chrono::duration_cast<std::chrono::nanoseconds>(6ms) - .count()); - mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>( - std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count())); + mTimeStats->recordFrameDuration(std::chrono::nanoseconds(1ms).count(), + std::chrono::nanoseconds(5ms).count()); + mTimeStats->recordRenderEngineDuration(std::chrono::nanoseconds(4ms).count(), + std::chrono::nanoseconds(6ms).count()); + mTimeStats->setPresentFenceGlobal( + std::make_shared<FenceTime>(std::chrono::nanoseconds(1ms).count())); mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::SurfaceFlingerCpuDeadlineMissed, 1, 2, 3}); @@ -847,6 +838,13 @@ TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) { mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::AppDeadlineMissed, 1, 2, 3}); mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerScheduling, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::PredictionError, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::AppDeadlineMissed | JankType::BufferStuffing, 1, 2, + 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::None, 1, 2, 3}); EXPECT_TRUE(inputCommand(InputCommand::CLEAR, FMT_STRING).empty()); @@ -996,6 +994,13 @@ TEST_F(TimeStatsTest, globalStatsCallback) { mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::AppDeadlineMissed, 1, 2, 3}); mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerScheduling, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::PredictionError, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::AppDeadlineMissed | JankType::BufferStuffing, 1, 2, + 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::None, 1, 2, 3}); EXPECT_THAT(mDelegate->mAtomTags, @@ -1007,8 +1012,8 @@ TEST_F(TimeStatsTest, globalStatsCallback) { std::string expectedFrameDuration = buildExpectedHistogramBytestring({2}, {1}); std::string expectedRenderEngineTiming = buildExpectedHistogramBytestring({1, 2}, {1, 1}); std::string expectedEmptyHistogram = buildExpectedHistogramBytestring({}, {}); - std::string expectedSfDeadlineMissed = buildExpectedHistogramBytestring({1}, {4}); - std::string expectedSfPredictionErrors = buildExpectedHistogramBytestring({2}, {4}); + std::string expectedSfDeadlineMissed = buildExpectedHistogramBytestring({1}, {7}); + std::string expectedSfPredictionErrors = buildExpectedHistogramBytestring({2}, {7}); { InSequence seq; @@ -1032,15 +1037,15 @@ TEST_F(TimeStatsTest, globalStatsCallback) { expectedRenderEngineTiming.c_str(), expectedRenderEngineTiming.size()), expectedRenderEngineTiming.size())); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 5)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 4)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 8)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 7)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 2)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, REFRESH_RATE_BUCKET_0)); EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, @@ -1096,6 +1101,13 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::AppDeadlineMissed, 1, 2, 3}); mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerScheduling, 1, 2, 2}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::PredictionError, 1, 2, 2}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::AppDeadlineMissed | JankType::BufferStuffing, 1, 2, + 2}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), JankType::None, 1, 2, 3}); EXPECT_THAT(mDelegate->mAtomTags, @@ -1111,7 +1123,7 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { std::string expectedDesiredToPresent = buildExpectedHistogramBytestring({1}, {1}); std::string expectedPostToAcquire = buildExpectedHistogramBytestring({1}, {1}); std::string expectedFrameRateOverride = frameRateVoteToProtoByteString(0.0, 0, 0); - std::string expectedAppDeadlineMissed = buildExpectedHistogramBytestring({3}, {4}); + std::string expectedAppDeadlineMissed = buildExpectedHistogramBytestring({3, 2}, {4, 3}); { InSequence seq; EXPECT_CALL(*mDelegate, @@ -1159,15 +1171,15 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, BAD_DESIRED_PRESENT_FRAMES)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, UID_0)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 5)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 4)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 8)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 7)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 2)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, REFRESH_RATE_BUCKET_0)); EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, RENDER_RATE_BUCKET_0)); EXPECT_CALL(*mDelegate, |