diff options
15 files changed, 678 insertions, 441 deletions
diff --git a/services/surfaceflinger/BufferLayer.cpp b/services/surfaceflinger/BufferLayer.cpp index ec81ff7b14..097f7de891 100644 --- a/services/surfaceflinger/BufferLayer.cpp +++ b/services/surfaceflinger/BufferLayer.cpp @@ -366,8 +366,11 @@ bool BufferLayer::onPostComposition(const DisplayDevice* display, mFrameTracker.setFrameReadyTime(desiredPresentTime); } + const Fps refreshRate = mFlinger->mRefreshRateConfigs->getCurrentRefreshRate().getFps(); + const std::optional<Fps> renderRate = mFlinger->mScheduler->getFrameRateOverride(getOwnerUid()); if (presentFence->isValid()) { - mFlinger->mTimeStats->setPresentFence(layerId, mCurrentFrameNumber, presentFence); + mFlinger->mTimeStats->setPresentFence(layerId, mCurrentFrameNumber, presentFence, + refreshRate, renderRate); mFlinger->mFrameTracer->traceFence(layerId, getCurrentBufferId(), mCurrentFrameNumber, presentFence, FrameTracer::FrameEvent::PRESENT_FENCE); mFrameTracker.setActualPresentFence(std::shared_ptr<FenceTime>(presentFence)); @@ -378,7 +381,8 @@ bool BufferLayer::onPostComposition(const DisplayDevice* display, // The HWC doesn't support present fences, so use the refresh // timestamp instead. const nsecs_t actualPresentTime = display->getRefreshTimestamp(); - mFlinger->mTimeStats->setPresentTime(layerId, mCurrentFrameNumber, actualPresentTime); + mFlinger->mTimeStats->setPresentTime(layerId, mCurrentFrameNumber, actualPresentTime, + refreshRate, renderRate); mFlinger->mFrameTracer->traceTimestamp(layerId, getCurrentBufferId(), mCurrentFrameNumber, actualPresentTime, FrameTracer::FrameEvent::PRESENT_FENCE); diff --git a/services/surfaceflinger/Fps.h b/services/surfaceflinger/Fps.h index 38a9af0149..e9f06e5519 100644 --- a/services/surfaceflinger/Fps.h +++ b/services/surfaceflinger/Fps.h @@ -27,7 +27,7 @@ namespace android { // Value which represents "frames per second". This class is a wrapper around // float, providing some useful utilities, such as comparisons with tolerance -// and converting between period duruation and frequency. +// and converting between period duration and frequency. class Fps { public: static constexpr Fps fromPeriodNsecs(nsecs_t period) { return Fps(1e9f / period, period); } diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index 3f833f4890..eb0c7244b3 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -320,6 +320,11 @@ void SurfaceFrame::setPresentState(PresentState presentState, nsecs_t lastLatchT mLastLatchTime = lastLatchTime; } +void SurfaceFrame::setRenderRate(Fps renderRate) { + std::lock_guard<std::mutex> lock(mMutex); + mRenderRate = renderRate; +} + std::optional<int32_t> SurfaceFrame::getJankType() const { std::scoped_lock lock(mMutex); if (mActuals.presentTime == 0) { @@ -367,6 +372,9 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t StringAppendF(&result, "%s", indent.c_str()); StringAppendF(&result, "Owner Pid : %d\n", mOwnerPid); StringAppendF(&result, "%s", indent.c_str()); + StringAppendF(&result, "Scheduled rendering rate: %d fps\n", + mRenderRate ? mRenderRate->getIntValue() : 0); + StringAppendF(&result, "%s", indent.c_str()); StringAppendF(&result, "Present State : %s\n", toString(mPresentState).c_str()); StringAppendF(&result, "%s", indent.c_str()); StringAppendF(&result, "Prediction State : %s\n", toString(mPredictionState).c_str()); @@ -391,9 +399,10 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime); } -void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, - nsecs_t vsyncPeriod) { +void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate, + nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta) { std::scoped_lock lock(mMutex); + if (mPresentState != PresentState::Presented) { // No need to update dropped buffers return; @@ -412,13 +421,16 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, mJankType = JankType::Unknown; mFramePresentMetadata = FramePresentMetadata::UnknownPresent; mFrameReadyMetadata = FrameReadyMetadata::UnknownFinish; - mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType); + const constexpr nsecs_t kAppDeadlineDelta = -1; + mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName, + mJankType, displayDeadlineDelta, displayPresentDelta, + kAppDeadlineDelta}); return; } const nsecs_t presentDelta = mActuals.presentTime - mPredictions.presentTime; const nsecs_t deadlineDelta = mActuals.endTime - mPredictions.endTime; - const nsecs_t deltaToVsync = std::abs(presentDelta) % vsyncPeriod; + const nsecs_t deltaToVsync = std::abs(presentDelta) % refreshRate.getPeriodNsecs(); if (deadlineDelta > mJankClassificationThresholds.deadlineThreshold) { mFrameReadyMetadata = FrameReadyMetadata::LateFinish; @@ -440,7 +452,8 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) { // Finish on time, Present early if (deltaToVsync < mJankClassificationThresholds.presentThreshold || - deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) { + deltaToVsync >= refreshRate.getPeriodNsecs() - + mJankClassificationThresholds.presentThreshold) { // Delta factor of vsync mJankType = JankType::SurfaceFlingerScheduling; } else { @@ -463,7 +476,8 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, mJankType |= displayFrameJankType; } else { if (deltaToVsync < mJankClassificationThresholds.presentThreshold || - deltaToVsync >= vsyncPeriod - mJankClassificationThresholds.presentThreshold) { + deltaToVsync >= refreshRate.getPeriodNsecs() - + mJankClassificationThresholds.presentThreshold) { // Delta factor of vsync mJankType |= JankType::SurfaceFlingerScheduling; } else { @@ -482,7 +496,8 @@ void SurfaceFrame::onPresent(nsecs_t presentTime, int32_t displayFrameJankType, } } } - mTimeStats->incrementJankyFrames(mOwnerUid, mLayerName, mJankType); + mTimeStats->incrementJankyFrames({refreshRate, mRenderRate, mOwnerUid, mLayerName, mJankType, + displayDeadlineDelta, displayPresentDelta, deadlineDelta}); } /** @@ -684,10 +699,10 @@ void FrameTimeline::addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame) mCurrentDisplayFrame->addSurfaceFrame(surfaceFrame); } -void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, nsecs_t vsyncPeriod) { +void FrameTimeline::setSfWakeUp(int64_t token, nsecs_t wakeUpTime, Fps refreshRate) { ATRACE_CALL(); std::scoped_lock lock(mMutex); - mCurrentDisplayFrame->onSfWakeUp(token, vsyncPeriod, + mCurrentDisplayFrame->onSfWakeUp(token, refreshRate, mTokenManager.getPredictionsForToken(token), wakeUpTime); } @@ -705,11 +720,11 @@ void FrameTimeline::DisplayFrame::addSurfaceFrame(std::shared_ptr<SurfaceFrame> mSurfaceFrames.push_back(surfaceFrame); } -void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, nsecs_t vsyncPeriod, +void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, Fps refreshRate, std::optional<TimelineItem> predictions, nsecs_t wakeUpTime) { mToken = token; - mVsyncPeriod = vsyncPeriod; + mRefreshRate = refreshRate; if (!predictions) { mPredictionState = PredictionState::Expired; } else { @@ -719,11 +734,6 @@ void FrameTimeline::DisplayFrame::onSfWakeUp(int64_t token, nsecs_t vsyncPeriod, mSurfaceFlingerActuals.startTime = wakeUpTime; } -void FrameTimeline::DisplayFrame::setTokenAndVsyncPeriod(int64_t token, nsecs_t vsyncPeriod) { - mToken = token; - mVsyncPeriod = vsyncPeriod; -} - void FrameTimeline::DisplayFrame::setPredictions(PredictionState predictionState, TimelineItem predictions) { mPredictionState = predictionState; @@ -740,14 +750,16 @@ void FrameTimeline::DisplayFrame::setActualEndTime(nsecs_t actualEndTime) { void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { mSurfaceFlingerActuals.presentTime = signalTime; - int32_t totalJankReasons = JankType::None; // Delta between the expected present and the actual present const nsecs_t presentDelta = mSurfaceFlingerActuals.presentTime - mSurfaceFlingerPredictions.presentTime; + const nsecs_t deadlineDelta = + mSurfaceFlingerActuals.endTime - mSurfaceFlingerPredictions.endTime; + // How far off was the presentDelta when compared to the vsyncPeriod. Used in checking if there // was a prediction error or not. - nsecs_t deltaToVsync = std::abs(presentDelta) % mVsyncPeriod; + nsecs_t deltaToVsync = std::abs(presentDelta) % mRefreshRate.getPeriodNsecs(); if (std::abs(presentDelta) > mJankClassificationThresholds.presentThreshold) { mFramePresentMetadata = presentDelta > 0 ? FramePresentMetadata::LatePresent : FramePresentMetadata::EarlyPresent; @@ -776,8 +788,8 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) { // Finish on time, Present early if (deltaToVsync < mJankClassificationThresholds.presentThreshold || - deltaToVsync >= - (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) { + deltaToVsync >= (mRefreshRate.getPeriodNsecs() - + mJankClassificationThresholds.presentThreshold)) { // Delta is a factor of vsync if its within the presentTheshold on either side // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms. @@ -797,8 +809,8 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { if (mFrameReadyMetadata == FrameReadyMetadata::OnTimeFinish) { // Finish on time, Present late if (deltaToVsync < mJankClassificationThresholds.presentThreshold || - deltaToVsync >= - (mVsyncPeriod - mJankClassificationThresholds.presentThreshold)) { + deltaToVsync >= (mRefreshRate.getPeriodNsecs() - + mJankClassificationThresholds.presentThreshold)) { // Delta is a factor of vsync if its within the presentTheshold on either side // of the vsyncPeriod. Example: 0-2ms and 9-11ms are both within the threshold // of the vsyncPeriod if the threshold was 2ms and the vsyncPeriod was 11ms. @@ -819,16 +831,9 @@ void FrameTimeline::DisplayFrame::onPresent(nsecs_t signalTime) { mJankType = JankType::Unknown; } } - totalJankReasons |= mJankType; - for (auto& surfaceFrame : mSurfaceFrames) { - surfaceFrame->onPresent(signalTime, mJankType, mVsyncPeriod); - auto surfaceFrameJankType = surfaceFrame->getJankType(); - if (surfaceFrameJankType != std::nullopt) { - totalJankReasons |= *surfaceFrameJankType; - } + surfaceFrame->onPresent(signalTime, mJankType, mRefreshRate, deadlineDelta, deltaToVsync); } - mTimeStats->incrementJankyFrames(totalJankReasons); } void FrameTimeline::DisplayFrame::trace(pid_t surfaceFlingerPid) const { @@ -988,7 +993,7 @@ void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) co StringAppendF(&result, "Present Metadata : %s\n", toString(mFramePresentMetadata).c_str()); StringAppendF(&result, "Finish Metadata: %s\n", toString(mFrameReadyMetadata).c_str()); StringAppendF(&result, "Start Metadata: %s\n", toString(mFrameStartMetadata).c_str()); - std::chrono::nanoseconds vsyncPeriod(mVsyncPeriod); + std::chrono::nanoseconds vsyncPeriod(mRefreshRate.getPeriodNsecs()); StringAppendF(&result, "Vsync Period: %10f\n", std::chrono::duration<double, std::milli>(vsyncPeriod).count()); nsecs_t presentDelta = @@ -996,7 +1001,7 @@ void FrameTimeline::DisplayFrame::dump(std::string& result, nsecs_t baseTime) co std::chrono::nanoseconds presentDeltaNs(std::abs(presentDelta)); StringAppendF(&result, "Present delta: %10f\n", std::chrono::duration<double, std::milli>(presentDeltaNs).count()); - std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mVsyncPeriod); + std::chrono::nanoseconds deltaToVsync(std::abs(presentDelta) % mRefreshRate.getPeriodNsecs()); StringAppendF(&result, "Present delta %% refreshrate: %10f\n", std::chrono::duration<double, std::milli>(deltaToVsync).count()); dumpTable(result, mSurfaceFlingerPredictions, mSurfaceFlingerActuals, "", mPredictionState, diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h index 54e8efbc92..4739106fdf 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h @@ -16,6 +16,7 @@ #pragma once +#include <../Fps.h> #include <../TimeStats/TimeStats.h> #include <gui/ISurfaceComposer.h> #include <gui/JankInfo.h> @@ -175,13 +176,17 @@ public: void setActualQueueTime(nsecs_t actualQueueTime); void setAcquireFenceTime(nsecs_t acquireFenceTime); void setPresentState(PresentState presentState, nsecs_t lastLatchTime = 0); + void setRenderRate(Fps renderRate); // Functions called by FrameTimeline // BaseTime is the smallest timestamp in this SurfaceFrame. // Used for dumping all timestamps relative to the oldest, making it easy to read. nsecs_t getBaseTime() const; // Sets the actual present time, appropriate metadata and classifies the jank. - void onPresent(nsecs_t presentTime, int32_t displayFrameJankType, nsecs_t vsyncPeriod); + // displayRefreshRate, displayDeadlineDelta, and displayPresentDelta are propagated from the + // display frame. + void onPresent(nsecs_t presentTime, int32_t displayFrameJankType, Fps refreshRate, + nsecs_t displayDeadlineDelta, nsecs_t displayPresentDelta); // All the timestamps are dumped relative to the baseTime void dump(std::string& result, const std::string& indent, nsecs_t baseTime) const; // Emits a packet for perfetto tracing. The function body will be executed only if tracing is @@ -216,6 +221,8 @@ private: int32_t mJankType GUARDED_BY(mMutex) = JankType::None; // Indicates if this frame was composited by the GPU or not bool mGpuComposition GUARDED_BY(mMutex) = false; + // Rendering rate for this frame. + std::optional<Fps> mRenderRate GUARDED_BY(mMutex); // Enum for the type of present FramePresentMetadata mFramePresentMetadata GUARDED_BY(mMutex) = FramePresentMetadata::UnknownPresent; @@ -255,7 +262,7 @@ public: // The first function called by SF for the current DisplayFrame. Fetches SF predictions based on // the token and sets the actualSfWakeTime for the current DisplayFrame. - virtual void setSfWakeUp(int64_t token, nsecs_t wakeupTime, nsecs_t vsyncPeriod) = 0; + virtual void setSfWakeUp(int64_t token, nsecs_t wakeupTime, Fps refreshRate) = 0; // Sets the sfPresentTime and finalizes the current DisplayFrame. Tracks the given present fence // until it's signaled, and updates the present timestamps of all presented SurfaceFrames in @@ -325,14 +332,13 @@ public: // is enabled. void trace(pid_t surfaceFlingerPid) const; // Sets the token, vsyncPeriod, predictions and SF start time. - void onSfWakeUp(int64_t token, nsecs_t vsyncPeriod, std::optional<TimelineItem> predictions, + void onSfWakeUp(int64_t token, Fps refreshRate, std::optional<TimelineItem> predictions, nsecs_t wakeUpTime); // Sets the appropriate metadata, classifies the jank and returns the classified jankType. void onPresent(nsecs_t signalTime); // Adds the provided SurfaceFrame to the current display frame. void addSurfaceFrame(std::shared_ptr<SurfaceFrame> surfaceFrame); - void setTokenAndVsyncPeriod(int64_t token, nsecs_t vsyncPeriod); void setPredictions(PredictionState predictionState, TimelineItem predictions); void setActualStartTime(nsecs_t actualStartTime); void setActualEndTime(nsecs_t actualEndTime); @@ -382,7 +388,7 @@ public: FrameStartMetadata mFrameStartMetadata = FrameStartMetadata::UnknownStart; // The refresh rate (vsync period) in nanoseconds as seen by SF during this DisplayFrame's // timeline - nsecs_t mVsyncPeriod = 0; + Fps mRefreshRate; // 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. @@ -398,7 +404,7 @@ public: const FrameTimelineInfo& frameTimelineInfo, pid_t ownerPid, uid_t ownerUid, std::string layerName, std::string debugName) override; void addSurfaceFrame(std::shared_ptr<frametimeline::SurfaceFrame> surfaceFrame) override; - void setSfWakeUp(int64_t token, nsecs_t wakeupTime, nsecs_t vsyncPeriod) override; + void setSfWakeUp(int64_t token, nsecs_t wakeupTime, Fps refreshRate) override; void setSfPresent(nsecs_t sfPresentTime, const std::shared_ptr<FenceTime>& presentFence) override; void parseArgs(const Vector<String16>& args, std::string& result) override; diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp index 27b2b87d77..6a28da30e7 100644 --- a/services/surfaceflinger/Layer.cpp +++ b/services/surfaceflinger/Layer.cpp @@ -1581,6 +1581,10 @@ std::shared_ptr<frametimeline::SurfaceFrame> Layer::createSurfaceFrameForTransac // For Transactions, the post time is considered to be both queue and acquire fence time. surfaceFrame->setActualQueueTime(postTime); surfaceFrame->setAcquireFenceTime(postTime); + const auto fps = mFlinger->mScheduler->getFrameRateOverride(getOwnerUid()); + if (fps) { + mSurfaceFrame->setRenderRate(*fps); + } onSurfaceFrameCreated(surfaceFrame); return surfaceFrame; } @@ -1592,6 +1596,10 @@ std::shared_ptr<frametimeline::SurfaceFrame> Layer::createSurfaceFrameForBuffer( debugName); // For buffers, acquire fence time will set during latch. surfaceFrame->setActualQueueTime(queueTime); + const auto fps = mFlinger->mScheduler->getFrameRateOverride(getOwnerUid()); + if (fps) { + mSurfaceFrame->setRenderRate(*fps); + } // TODO(b/178542907): Implement onSurfaceFrameCreated for BQLayer as well. onSurfaceFrameCreated(surfaceFrame); return surfaceFrame; diff --git a/services/surfaceflinger/Scheduler/Scheduler.h b/services/surfaceflinger/Scheduler/Scheduler.h index 5237516f17..0e9eba731a 100644 --- a/services/surfaceflinger/Scheduler/Scheduler.h +++ b/services/surfaceflinger/Scheduler/Scheduler.h @@ -174,6 +174,8 @@ public: // Stores the preferred refresh rate that an app should run at. // FrameRateOverride.refreshRateHz == 0 means no preference. void setPreferredRefreshRateForUid(FrameRateOverride) EXCLUDES(mFrameRateOverridesMutex); + // Retrieves the overridden refresh rate for a given uid. + std::optional<Fps> getFrameRateOverride(uid_t uid) const EXCLUDES(mFrameRateOverridesMutex); private: friend class TestableScheduler; @@ -236,7 +238,6 @@ private: Fps displayRefreshRate) REQUIRES(mFeatureStateLock) EXCLUDES(mFrameRateOverridesMutex); - std::optional<Fps> getFrameRateOverride(uid_t uid) const EXCLUDES(mFrameRateOverridesMutex); impl::EventThread::ThrottleVsyncCallback makeThrottleVsyncCallback() const; // Stores EventThread associated with a given VSyncSource, and an initial EventThreadConnection. diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index a36502cea1..7fada820e4 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -1899,7 +1899,7 @@ void SurfaceFlinger::onMessageInvalidate(int64_t vsyncId, nsecs_t expectedVSyncT const bool tracePreComposition = mTracingEnabled && !mTracePostComposition; ConditionalLockGuard<std::mutex> lock(mTracingLock, tracePreComposition); - mFrameTimeline->setSfWakeUp(vsyncId, frameStart, stats.vsyncPeriod); + mFrameTimeline->setSfWakeUp(vsyncId, frameStart, Fps::fromPeriodNsecs(stats.vsyncPeriod)); refreshNeeded = handleMessageTransaction(); refreshNeeded |= handleMessageInvalidate(); diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp index 5d387d68e8..b93f30ebbf 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.cpp +++ b/services/surfaceflinger/TimeStats/TimeStats.cpp @@ -105,53 +105,63 @@ std::string frameRateVoteToProtoByteString(float refreshRate, int frameRateCompa AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventList* data) { std::lock_guard<std::mutex> lock(mMutex); - if (mTimeStats.statsStart == 0) { + if (mTimeStats.statsStartLegacy == 0) { return AStatsManager_PULL_SKIP; } flushPowerTimeLocked(); - AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data); - mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_GLOBAL_INFO); - mStatsDelegate->statsEventWriteInt64(event, mTimeStats.totalFrames); - mStatsDelegate->statsEventWriteInt64(event, mTimeStats.missedFrames); - mStatsDelegate->statsEventWriteInt64(event, mTimeStats.clientCompositionFrames); - mStatsDelegate->statsEventWriteInt64(event, mTimeStats.displayOnTime); - mStatsDelegate->statsEventWriteInt64(event, mTimeStats.presentToPresent.totalTime()); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.displayEventConnectionsCount); - std::string frameDurationBytes = - histogramToProtoByteString(mTimeStats.frameDuration.hist, mMaxPulledHistogramBuckets); - mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)frameDurationBytes.c_str(), - frameDurationBytes.size()); - std::string renderEngineTimingBytes = - histogramToProtoByteString(mTimeStats.renderEngineTiming.hist, - mMaxPulledHistogramBuckets); - mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)renderEngineTimingBytes.c_str(), - renderEngineTimingBytes.size()); - - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.jankPayload.totalFrames); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.jankPayload.totalJankyFrames); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.jankPayload.totalSFLongCpu); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.jankPayload.totalSFLongGpu); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.jankPayload.totalSFUnattributed); - mStatsDelegate->statsEventWriteInt32(event, mTimeStats.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, 0); // display_refresh_rate_bucket - std::string sfDeadlineMissedBytes = - histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(), - mMaxPulledHistogramBuckets); - mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)sfDeadlineMissedBytes.c_str(), - sfDeadlineMissedBytes.size()); // sf_deadline_misses - std::string sfPredictionErrorBytes = - histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(), - mMaxPulledHistogramBuckets); - mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)sfPredictionErrorBytes.c_str(), - sfPredictionErrorBytes.size()); // sf_prediction_errors - mStatsDelegate->statsEventWriteInt32(event, 0); // render_rate_bucket - mStatsDelegate->statsEventBuild(event); + for (const auto& globalSlice : mTimeStats.stats) { + AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data); + mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_GLOBAL_INFO); + mStatsDelegate->statsEventWriteInt64(event, mTimeStats.totalFramesLegacy); + mStatsDelegate->statsEventWriteInt64(event, mTimeStats.missedFramesLegacy); + mStatsDelegate->statsEventWriteInt64(event, mTimeStats.clientCompositionFramesLegacy); + mStatsDelegate->statsEventWriteInt64(event, mTimeStats.displayOnTimeLegacy); + mStatsDelegate->statsEventWriteInt64(event, mTimeStats.presentToPresentLegacy.totalTime()); + mStatsDelegate->statsEventWriteInt32(event, mTimeStats.displayEventConnectionsCountLegacy); + std::string frameDurationBytes = + histogramToProtoByteString(mTimeStats.frameDurationLegacy.hist, + mMaxPulledHistogramBuckets); + mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)frameDurationBytes.c_str(), + frameDurationBytes.size()); + std::string renderEngineTimingBytes = + histogramToProtoByteString(mTimeStats.renderEngineTimingLegacy.hist, + mMaxPulledHistogramBuckets); + mStatsDelegate->statsEventWriteByteArray(event, + (const uint8_t*)renderEngineTimingBytes.c_str(), + renderEngineTimingBytes.size()); + + mStatsDelegate->statsEventWriteInt32(event, globalSlice.second.jankPayload.totalFrames); + mStatsDelegate->statsEventWriteInt32(event, + globalSlice.second.jankPayload.totalJankyFrames); + mStatsDelegate->statsEventWriteInt32(event, globalSlice.second.jankPayload.totalSFLongCpu); + mStatsDelegate->statsEventWriteInt32(event, globalSlice.second.jankPayload.totalSFLongGpu); + mStatsDelegate->statsEventWriteInt32(event, + 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.first.displayRefreshRateBucket); + std::string sfDeadlineMissedBytes = + histogramToProtoByteString(globalSlice.second.displayDeadlineDeltas.hist, + mMaxPulledHistogramBuckets); + mStatsDelegate->statsEventWriteByteArray(event, + (const uint8_t*)sfDeadlineMissedBytes.c_str(), + sfDeadlineMissedBytes.size()); + std::string sfPredictionErrorBytes = + histogramToProtoByteString(globalSlice.second.displayPresentDeltas.hist, + mMaxPulledHistogramBuckets); + mStatsDelegate->statsEventWriteByteArray(event, + (const uint8_t*)sfPredictionErrorBytes.c_str(), + sfPredictionErrorBytes.size()); + mStatsDelegate->statsEventWriteInt32(event, globalSlice.first.renderRateBucket); + mStatsDelegate->statsEventBuild(event); + } + clearGlobalLocked(); return AStatsManager_PULL_SUCCESS; @@ -160,9 +170,18 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventLi AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventList* data) { std::lock_guard<std::mutex> lock(mMutex); - std::vector<TimeStatsHelper::TimeStatsLayer const*> dumpStats; - for (const auto& ele : mTimeStats.stats) { - dumpStats.push_back(&ele.second); + std::vector<TimeStatsHelper::TimeStatsLayer*> dumpStats; + uint32_t numLayers = 0; + for (const auto& globalSlice : mTimeStats.stats) { + numLayers += globalSlice.second.stats.size(); + } + + dumpStats.reserve(numLayers); + + for (auto& globalSlice : mTimeStats.stats) { + for (auto& layerSlice : globalSlice.second.stats) { + dumpStats.push_back(&layerSlice.second); + } } std::sort(dumpStats.begin(), dumpStats.end(), @@ -175,7 +194,7 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis dumpStats.resize(mMaxPulledLayers); } - for (const auto& layer : dumpStats) { + for (auto& layer : dumpStats) { AStatsEvent* event = mStatsDelegate->addStatsEventToPullData(data); mStatsDelegate->statsEventSetAtomId(event, android::util::SURFACEFLINGER_STATS_LAYER_INFO); mStatsDelegate->statsEventWriteString8(event, layer->layerName.c_str()); @@ -208,17 +227,18 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis 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, 0); // display_refresh_rate_bucket - mStatsDelegate->statsEventWriteInt32(event, 0); // render_rate_bucket + mStatsDelegate->statsEventWriteInt32( + event, layer->displayRefreshRateBucket); // display_refresh_rate_bucket + mStatsDelegate->statsEventWriteInt32(event, layer->renderRateBucket); // render_rate_bucket std::string frameRateVoteBytes = frameRateVoteToProtoByteString(0.0, 0, 0); mStatsDelegate->statsEventWriteByteArray(event, (const uint8_t*)frameRateVoteBytes.c_str(), frameRateVoteBytes.size()); // set_frame_rate_vote std::string appDeadlineMissedBytes = - histogramToProtoByteString(std::unordered_map<int32_t, int32_t>(), + histogramToProtoByteString(layer->deltas["appDeadlineDeltas"].hist, mMaxPulledHistogramBuckets); - mStatsDelegate - ->statsEventWriteByteArray(event, (const uint8_t*)appDeadlineMissedBytes.c_str(), - appDeadlineMissedBytes.size()); // app_deadline_misses + mStatsDelegate->statsEventWriteByteArray(event, + (const uint8_t*)appDeadlineMissedBytes.c_str(), + appDeadlineMissedBytes.size()); mStatsDelegate->statsEventBuild(event); } @@ -310,7 +330,7 @@ void TimeStats::incrementTotalFrames() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.totalFrames++; + mTimeStats.totalFramesLegacy++; } void TimeStats::incrementMissedFrames() { @@ -319,7 +339,7 @@ void TimeStats::incrementMissedFrames() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.missedFrames++; + mTimeStats.missedFramesLegacy++; } void TimeStats::incrementClientCompositionFrames() { @@ -328,7 +348,7 @@ void TimeStats::incrementClientCompositionFrames() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.clientCompositionFrames++; + mTimeStats.clientCompositionFramesLegacy++; } void TimeStats::incrementClientCompositionReusedFrames() { @@ -337,7 +357,7 @@ void TimeStats::incrementClientCompositionReusedFrames() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.clientCompositionReusedFrames++; + mTimeStats.clientCompositionReusedFramesLegacy++; } void TimeStats::incrementRefreshRateSwitches() { @@ -346,7 +366,7 @@ void TimeStats::incrementRefreshRateSwitches() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.refreshRateSwitches++; + mTimeStats.refreshRateSwitchesLegacy++; } void TimeStats::incrementCompositionStrategyChanges() { @@ -355,7 +375,7 @@ void TimeStats::incrementCompositionStrategyChanges() { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.compositionStrategyChanges++; + mTimeStats.compositionStrategyChangesLegacy++; } void TimeStats::recordDisplayEventConnectionCount(int32_t count) { @@ -364,8 +384,8 @@ void TimeStats::recordDisplayEventConnectionCount(int32_t count) { ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - mTimeStats.displayEventConnectionsCount = - std::max(mTimeStats.displayEventConnectionsCount, count); + mTimeStats.displayEventConnectionsCountLegacy = + std::max(mTimeStats.displayEventConnectionsCountLegacy, count); } static int32_t msBetween(nsecs_t start, nsecs_t end) { @@ -381,7 +401,7 @@ void TimeStats::recordFrameDuration(nsecs_t startTime, nsecs_t endTime) { std::lock_guard<std::mutex> lock(mMutex); if (mPowerTime.powerMode == PowerMode::ON) { - mTimeStats.frameDuration.insert(msBetween(startTime, endTime)); + mTimeStats.frameDurationLegacy.insert(msBetween(startTime, endTime)); } } @@ -444,12 +464,22 @@ bool TimeStats::recordReadyLocked(int32_t layerId, TimeRecord* timeRecord) { return true; } -void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) { +static int32_t clampToSmallestBucket(Fps fps, size_t bucketWidth) { + return (fps.getIntValue() / bucketWidth) * bucketWidth; +} + +void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId, Fps displayRefreshRate, + std::optional<Fps> renderRate) { ATRACE_CALL(); LayerRecord& layerRecord = mTimeStatsTracker[layerId]; TimeRecord& prevTimeRecord = layerRecord.prevTimeRecord; std::deque<TimeRecord>& timeRecords = layerRecord.timeRecords; + const int32_t refreshRateBucket = + clampToSmallestBucket(displayRefreshRate, REFRESH_RATE_BUCKET_WIDTH); + const int32_t renderRateBucket = + clampToSmallestBucket(renderRate ? *renderRate : displayRefreshRate, + RENDER_RATE_BUCKET_WIDTH); while (!timeRecords.empty()) { if (!recordReadyLocked(layerId, &timeRecords[0])) break; ALOGV("[%d]-[%" PRIu64 "]-presentFenceTime[%" PRId64 "]", layerId, @@ -458,11 +488,21 @@ void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) { if (prevTimeRecord.ready) { uid_t uid = layerRecord.uid; const std::string& layerName = layerRecord.layerName; - if (!mTimeStats.stats.count({uid, layerName})) { - mTimeStats.stats[{uid, layerName}].uid = uid; - mTimeStats.stats[{uid, layerName}].layerName = layerName; + TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket}; + if (!mTimeStats.stats.count(timelineKey)) { + mTimeStats.stats[timelineKey].key = timelineKey; } - TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[{uid, layerName}]; + + TimeStatsHelper::TimelineStats& displayStats = mTimeStats.stats[timelineKey]; + + TimeStatsHelper::LayerStatsKey layerKey = {uid, layerName}; + if (!displayStats.stats.count(layerKey)) { + displayStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket; + displayStats.stats[layerKey].renderRateBucket = renderRateBucket; + displayStats.stats[layerKey].uid = uid; + displayStats.stats[layerKey].layerName = layerName; + } + TimeStatsHelper::TimeStatsLayer& timeStatsLayer = displayStats.stats[layerKey]; timeStatsLayer.totalFrames++; timeStatsLayer.droppedFrames += layerRecord.droppedFrames; timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames; @@ -524,8 +564,16 @@ static bool layerNameIsValid(const std::string& layerName) { } bool TimeStats::canAddNewAggregatedStats(uid_t uid, const std::string& layerName) { - return mTimeStats.stats.count({uid, layerName}) > 0 || - mTimeStats.stats.size() < MAX_NUM_LAYER_STATS; + uint32_t layerRecords = 0; + for (const auto& record : mTimeStats.stats) { + if (record.second.stats.count({uid, layerName}) > 0) { + return true; + } + + layerRecords += record.second.stats.size(); + } + + return mTimeStats.stats.size() < MAX_NUM_LAYER_STATS; } void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName, @@ -676,7 +724,8 @@ void TimeStats::setAcquireFence(int32_t layerId, uint64_t frameNumber, } } -void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) { +void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime, + Fps displayRefreshRate, std::optional<Fps> renderRate) { if (!mEnabled.load()) return; ATRACE_CALL(); @@ -695,11 +744,12 @@ void TimeStats::setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t pr layerRecord.waitData++; } - flushAvailableRecordsToStatsLocked(layerId); + flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate); } void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, - const std::shared_ptr<FenceTime>& presentFence) { + const std::shared_ptr<FenceTime>& presentFence, + Fps displayRefreshRate, std::optional<Fps> renderRate) { if (!mEnabled.load()) return; ATRACE_CALL(); @@ -719,16 +769,17 @@ void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, layerRecord.waitData++; } - flushAvailableRecordsToStatsLocked(layerId); + flushAvailableRecordsToStatsLocked(layerId, displayRefreshRate, renderRate); } +static const constexpr int32_t kValidJankyReason = JankType::SurfaceFlingerCpuDeadlineMissed | + JankType::SurfaceFlingerGpuDeadlineMissed | JankType::AppDeadlineMissed | + JankType::DisplayHAL; + template <class T> static void updateJankPayload(T& t, int32_t reasons) { t.jankPayload.totalFrames++; - static const constexpr int32_t kValidJankyReason = JankType::SurfaceFlingerCpuDeadlineMissed | - JankType::SurfaceFlingerGpuDeadlineMissed | JankType::AppDeadlineMissed | - JankType::DisplayHAL; if (reasons & kValidJankyReason) { t.jankPayload.totalJankyFrames++; if ((reasons & JankType::SurfaceFlingerCpuDeadlineMissed) != 0) { @@ -746,16 +797,7 @@ static void updateJankPayload(T& t, int32_t reasons) { } } -void TimeStats::incrementJankyFrames(int32_t reasons) { - if (!mEnabled.load()) return; - - ATRACE_CALL(); - std::lock_guard<std::mutex> lock(mMutex); - - updateJankPayload<TimeStatsHelper::TimeStatsGlobal>(mTimeStats, reasons); -} - -void TimeStats::incrementJankyFrames(uid_t uid, const std::string& layerName, int32_t reasons) { +void TimeStats::incrementJankyFrames(const JankyFramesInfo& info) { if (!mEnabled.load()) return; ATRACE_CALL(); @@ -772,17 +814,44 @@ void TimeStats::incrementJankyFrames(uid_t uid, const std::string& layerName, in // TimeStats will flush the first present fence for a layer *before* FrameTimeline does so that // the first jank record is not dropped. - bool useDefaultLayerKey = false; static const std::string kDefaultLayerName = "none"; - if (!mTimeStats.stats.count({uid, layerName})) { - mTimeStats.stats[{uid, kDefaultLayerName}].uid = uid; - mTimeStats.stats[{uid, kDefaultLayerName}].layerName = kDefaultLayerName; - useDefaultLayerKey = true; + + const int32_t refreshRateBucket = + clampToSmallestBucket(info.refreshRate, REFRESH_RATE_BUCKET_WIDTH); + const int32_t renderRateBucket = + clampToSmallestBucket(info.renderRate ? *info.renderRate : info.refreshRate, + RENDER_RATE_BUCKET_WIDTH); + const TimeStatsHelper::TimelineStatsKey timelineKey = {refreshRateBucket, renderRateBucket}; + + if (!mTimeStats.stats.count(timelineKey)) { + mTimeStats.stats[timelineKey].key = timelineKey; } - TimeStatsHelper::TimeStatsLayer& timeStatsLayer = - mTimeStats.stats[{uid, useDefaultLayerKey ? kDefaultLayerName : layerName}]; - updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, reasons); + TimeStatsHelper::TimelineStats& timelineStats = mTimeStats.stats[timelineKey]; + + updateJankPayload<TimeStatsHelper::TimelineStats>(timelineStats, info.reasons); + + TimeStatsHelper::LayerStatsKey layerKey = {info.uid, info.layerName}; + if (!timelineStats.stats.count(layerKey)) { + layerKey = {info.uid, kDefaultLayerName}; + timelineStats.stats[layerKey].displayRefreshRateBucket = refreshRateBucket; + timelineStats.stats[layerKey].renderRateBucket = renderRateBucket; + timelineStats.stats[layerKey].uid = info.uid; + timelineStats.stats[layerKey].layerName = kDefaultLayerName; + } + + TimeStatsHelper::TimeStatsLayer& timeStatsLayer = timelineStats.stats[layerKey]; + updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, info.reasons); + + if (info.reasons & kValidJankyReason) { + // TimeStats Histograms only retain positive values, so we don't need to check if these + // deadlines were really missed if we know that the frame had jank, since deadlines + // that were met will be dropped. + timelineStats.displayDeadlineDeltas.insert(static_cast<int32_t>(info.displayDeadlineDelta)); + timelineStats.displayPresentDeltas.insert(static_cast<int32_t>(info.displayPresentJitter)); + timeStatsLayer.deltas["appDeadlineDeltas"].insert( + static_cast<int32_t>(info.appDeadlineDelta)); + } } void TimeStats::onDestroy(int32_t layerId) { @@ -823,7 +892,7 @@ void TimeStats::flushPowerTimeLocked() { switch (mPowerTime.powerMode) { case PowerMode::ON: - mTimeStats.displayOnTime += elapsedTime; + mTimeStats.displayOnTimeLegacy += elapsedTime; break; case PowerMode::OFF: case PowerMode::DOZE: @@ -852,10 +921,10 @@ void TimeStats::setPowerMode(PowerMode powerMode) { void TimeStats::recordRefreshRate(uint32_t fps, nsecs_t duration) { std::lock_guard<std::mutex> lock(mMutex); - if (mTimeStats.refreshRateStats.count(fps)) { - mTimeStats.refreshRateStats[fps] += duration; + if (mTimeStats.refreshRateStatsLegacy.count(fps)) { + mTimeStats.refreshRateStatsLegacy[fps] += duration; } else { - mTimeStats.refreshRateStats.insert({fps, duration}); + mTimeStats.refreshRateStatsLegacy.insert({fps, duration}); } } @@ -881,7 +950,7 @@ void TimeStats::flushAvailableGlobalRecordsToStatsLocked() { msBetween(mGlobalRecord.prevPresentTime, curPresentTime); ALOGV("Global present2present[%d] prev[%" PRId64 "] curr[%" PRId64 "]", presentToPresentMs, mGlobalRecord.prevPresentTime, curPresentTime); - mTimeStats.presentToPresent.insert(presentToPresentMs); + mTimeStats.presentToPresentLegacy.insert(presentToPresentMs); } mGlobalRecord.prevPresentTime = curPresentTime; @@ -908,7 +977,7 @@ void TimeStats::flushAvailableGlobalRecordsToStatsLocked() { } const int32_t renderEngineMs = msBetween(duration.startTime, endNs); - mTimeStats.renderEngineTiming.insert(renderEngineMs); + mTimeStats.renderEngineTimingLegacy.insert(renderEngineMs); mGlobalRecord.renderEngineDurations.pop_front(); } @@ -951,7 +1020,7 @@ void TimeStats::enable() { std::lock_guard<std::mutex> lock(mMutex); mEnabled.store(true); - mTimeStats.statsStart = static_cast<int64_t>(std::time(0)); + mTimeStats.statsStartLegacy = static_cast<int64_t>(std::time(0)); mPowerTime.prevTime = systemTime(); ALOGD("Enabled"); } @@ -964,7 +1033,7 @@ void TimeStats::disable() { std::lock_guard<std::mutex> lock(mMutex); flushPowerTimeLocked(); mEnabled.store(false); - mTimeStats.statsEnd = static_cast<int64_t>(std::time(0)); + mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0)); ALOGD("Disabled"); } @@ -977,21 +1046,20 @@ void TimeStats::clearAll() { void TimeStats::clearGlobalLocked() { ATRACE_CALL(); - mTimeStats.statsStart = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0); - mTimeStats.statsEnd = 0; - mTimeStats.totalFrames = 0; - mTimeStats.missedFrames = 0; - mTimeStats.clientCompositionFrames = 0; - mTimeStats.clientCompositionReusedFrames = 0; - mTimeStats.refreshRateSwitches = 0; - mTimeStats.compositionStrategyChanges = 0; - mTimeStats.displayEventConnectionsCount = 0; - mTimeStats.displayOnTime = 0; - mTimeStats.presentToPresent.hist.clear(); - mTimeStats.frameDuration.hist.clear(); - mTimeStats.renderEngineTiming.hist.clear(); - mTimeStats.jankPayload = TimeStatsHelper::JankPayload(); - mTimeStats.refreshRateStats.clear(); + mTimeStats.statsStartLegacy = (mEnabled.load() ? static_cast<int64_t>(std::time(0)) : 0); + mTimeStats.statsEndLegacy = 0; + mTimeStats.totalFramesLegacy = 0; + mTimeStats.missedFramesLegacy = 0; + mTimeStats.clientCompositionFramesLegacy = 0; + mTimeStats.clientCompositionReusedFramesLegacy = 0; + mTimeStats.refreshRateSwitchesLegacy = 0; + mTimeStats.compositionStrategyChangesLegacy = 0; + mTimeStats.displayEventConnectionsCountLegacy = 0; + mTimeStats.displayOnTimeLegacy = 0; + mTimeStats.presentToPresentLegacy.hist.clear(); + mTimeStats.frameDurationLegacy.hist.clear(); + mTimeStats.renderEngineTimingLegacy.hist.clear(); + mTimeStats.refreshRateStatsLegacy.clear(); mPowerTime.prevTime = systemTime(); mGlobalRecord.prevPresentTime = 0; mGlobalRecord.presentFences.clear(); @@ -1014,11 +1082,11 @@ void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::strin ATRACE_CALL(); std::lock_guard<std::mutex> lock(mMutex); - if (mTimeStats.statsStart == 0) { + if (mTimeStats.statsStartLegacy == 0) { return; } - mTimeStats.statsEnd = static_cast<int64_t>(std::time(0)); + mTimeStats.statsEndLegacy = static_cast<int64_t>(std::time(0)); flushPowerTimeLocked(); diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h index df40ef6933..fd112b95b0 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.h +++ b/services/surfaceflinger/TimeStats/TimeStats.h @@ -27,12 +27,13 @@ // TODO(b/129481165): remove the #pragma below and fix conversion issues #pragma clang diagnostic pop // ignored "-Wconversion -Wextra" +#include <../Fps.h> +#include <gui/JankInfo.h> #include <stats_event.h> #include <stats_pull_atom_callback.h> #include <statslog.h> #include <timestatsproto/TimeStatsHelper.h> #include <timestatsproto/TimeStatsProtoHeader.h> -#include <gui/JankInfo.h> #include <ui/FenceTime.h> #include <utils/String16.h> #include <utils/Vector.h> @@ -108,23 +109,60 @@ public: const std::shared_ptr<FenceTime>& acquireFence) = 0; // SetPresent{Time, Fence} are not expected to be called in the critical // rendering path, as they flush prior fences if those fences have fired. - virtual void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) = 0; + virtual void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime, + Fps displayRefreshRate, std::optional<Fps> renderRate) = 0; virtual void setPresentFence(int32_t layerId, uint64_t frameNumber, - const std::shared_ptr<FenceTime>& presentFence) = 0; - - // Increments janky frames, tracked globally. Because FrameTimeline is the infrastructure - // responsible for computing jank in the system, this is expected to be called from - // FrameTimeline, rather than directly from SurfaceFlinger or individual layers. If there are no - // jank reasons, then total frames are incremented but jank is not, for accurate accounting of - // janky frames. - virtual void incrementJankyFrames(int32_t reasons) = 0; - // Increments janky frames, blamed to the provided {uid, layerName} key, with JankMetadata as - // supplementary reasons for the jank. Because FrameTimeline is the infrastructure responsible - // for computing jank in the system, this is expected to be called from FrameTimeline, rather - // than directly from SurfaceFlinger or individual layers. - // If there are no jank reasons, then total frames are incremented but jank is not, for accurate + const std::shared_ptr<FenceTime>& presentFence, + Fps displayRefreshRate, std::optional<Fps> renderRate) = 0; + + // Increments janky frames, blamed to the provided {refreshRate, renderRate, uid, layerName} + // key, with JankMetadata as supplementary reasons for the jank. Because FrameTimeline is the + // infrastructure responsible for computing jank in the system, this is expected to be called + // from FrameTimeline, rather than directly from SurfaceFlinger or individual layers. If there + // are no jank reasons, then total frames are incremented but jank is not, for accurate // accounting of janky frames. - virtual void incrementJankyFrames(uid_t uid, const std::string& layerName, int32_t reasons) = 0; + // displayDeadlineDelta, displayPresentJitter, and appDeadlineDelta are also provided in order + // to provide contextual information about a janky frame. These values may only be uploaded if + // there was an associated valid jank reason, and they must be positive. When these frame counts + // are incremented, these are also aggregated into a global reporting packet to help with data + // validation and assessing of overall device health. + struct JankyFramesInfo { + Fps refreshRate; + std::optional<Fps> renderRate; + uid_t uid = 0; + std::string layerName; + int32_t reasons = 0; + nsecs_t displayDeadlineDelta = 0; + nsecs_t displayPresentJitter = 0; + nsecs_t appDeadlineDelta = 0; + + bool operator==(const JankyFramesInfo& o) const { + return Fps::EqualsInBuckets{}(refreshRate, o.refreshRate) && + ((renderRate == std::nullopt && o.renderRate == std::nullopt) || + (renderRate != std::nullopt && o.renderRate != std::nullopt && + Fps::EqualsInBuckets{}(*renderRate, *o.renderRate))) && + uid == o.uid && layerName == o.layerName && reasons == o.reasons && + displayDeadlineDelta == o.displayDeadlineDelta && + displayPresentJitter == o.displayPresentJitter && + appDeadlineDelta == o.appDeadlineDelta; + } + + friend std::ostream& operator<<(std::ostream& os, const JankyFramesInfo& info) { + os << "JankyFramesInfo {"; + os << "\n .refreshRate = " << info.refreshRate; + os << "\n .renderRate = " + << (info.renderRate ? to_string(*info.renderRate) : "nullopt"); + os << "\n .uid = " << info.uid; + os << "\n .layerName = " << info.layerName; + os << "\n .reasons = " << info.reasons; + os << "\n .displayDeadlineDelta = " << info.displayDeadlineDelta; + os << "\n .displayPresentJitter = " << info.displayPresentJitter; + os << "\n .appDeadlineDelta = " << info.appDeadlineDelta; + return os << "\n}"; + } + }; + + virtual void incrementJankyFrames(const JankyFramesInfo& info) = 0; // Clean up the layer record virtual void onDestroy(int32_t layerId) = 0; // If SF skips or rejects a buffer, remove the corresponding TimeRecord. @@ -268,11 +306,13 @@ public: void setAcquireTime(int32_t layerId, uint64_t frameNumber, nsecs_t acquireTime) override; void setAcquireFence(int32_t layerId, uint64_t frameNumber, const std::shared_ptr<FenceTime>& acquireFence) override; - void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) override; + void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime, + Fps displayRefreshRate, std::optional<Fps> renderRate) override; void setPresentFence(int32_t layerId, uint64_t frameNumber, - const std::shared_ptr<FenceTime>& presentFence) override; - void incrementJankyFrames(int32_t reasons) override; - void incrementJankyFrames(uid_t uid, const std::string& layerName, int32_t reasons) override; + const std::shared_ptr<FenceTime>& presentFence, Fps displayRefreshRate, + std::optional<Fps> renderRate) override; + + void incrementJankyFrames(const JankyFramesInfo& info) override; // Clean up the layer record void onDestroy(int32_t layerId) override; // If SF skips or rejects a buffer, remove the corresponding TimeRecord. @@ -293,7 +333,8 @@ private: AStatsManager_PullAtomCallbackReturn populateGlobalAtom(AStatsEventList* data); AStatsManager_PullAtomCallbackReturn populateLayerAtom(AStatsEventList* data); bool recordReadyLocked(int32_t layerId, TimeRecord* timeRecord); - void flushAvailableRecordsToStatsLocked(int32_t layerId); + void flushAvailableRecordsToStatsLocked(int32_t layerId, Fps displayRefreshRate, + std::optional<Fps> renderRate); void flushPowerTimeLocked(); void flushAvailableGlobalRecordsToStatsLocked(); bool canAddNewAggregatedStats(uid_t uid, const std::string& layerName); @@ -314,6 +355,9 @@ private: GlobalRecord mGlobalRecord; static const size_t MAX_NUM_LAYER_RECORDS = 200; + + static const size_t REFRESH_RATE_BUCKET_WIDTH = 30; + static const size_t RENDER_RATE_BUCKET_WIDTH = REFRESH_RATE_BUCKET_WIDTH; static const size_t MAX_NUM_LAYER_STATS = 200; static const size_t MAX_NUM_PULLED_LAYERS = MAX_NUM_LAYER_STATS; std::unique_ptr<StatsEventDelegate> mStatsDelegate = std::make_unique<StatsEventDelegate>(); diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp index 0fb748f1a6..814f046c3b 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp +++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp @@ -41,7 +41,7 @@ void TimeStatsHelper::Histogram::insert(int32_t delta) { if (delta < 0) return; // std::lower_bound won't work on out of range values if (delta > histogramConfig[HISTOGRAM_SIZE - 1]) { - hist[histogramConfig[HISTOGRAM_SIZE - 1]] += delta / histogramConfig[HISTOGRAM_SIZE - 1]; + hist[histogramConfig[HISTOGRAM_SIZE - 1]]++; return; } auto iter = std::lower_bound(histogramConfig.begin(), histogramConfig.end(), delta); @@ -90,6 +90,8 @@ std::string TimeStatsHelper::JankPayload::toString() const { std::string TimeStatsHelper::TimeStatsLayer::toString() const { std::string result = "\n"; + StringAppendF(&result, "displayRefreshRate = %d fps\n", displayRefreshRateBucket); + StringAppendF(&result, "renderRate = %d fps\n", renderRateBucket); StringAppendF(&result, "uid = %d\n", uid); StringAppendF(&result, "layerName = %s\n", layerName.c_str()); StringAppendF(&result, "packageName = %s\n", packageName.c_str()); @@ -115,35 +117,49 @@ std::string TimeStatsHelper::TimeStatsLayer::toString() const { std::string TimeStatsHelper::TimeStatsGlobal::toString(std::optional<uint32_t> maxLayers) const { std::string result = "SurfaceFlinger TimeStats:\n"; - StringAppendF(&result, "statsStart = %" PRId64 "\n", statsStart); - StringAppendF(&result, "statsEnd = %" PRId64 "\n", statsEnd); - StringAppendF(&result, "totalFrames = %d\n", totalFrames); - StringAppendF(&result, "missedFrames = %d\n", missedFrames); - StringAppendF(&result, "clientCompositionFrames = %d\n", clientCompositionFrames); - StringAppendF(&result, "clientCompositionReusedFrames = %d\n", clientCompositionReusedFrames); - StringAppendF(&result, "refreshRateSwitches = %d\n", refreshRateSwitches); - StringAppendF(&result, "compositionStrategyChanges = %d\n", compositionStrategyChanges); - StringAppendF(&result, "displayOnTime = %" PRId64 " ms\n", displayOnTime); - result.append("Global aggregated jank payload:\n"); - result.append(jankPayload.toString()); + result.append("Legacy stats are as follows:\n"); + StringAppendF(&result, "statsStart = %" PRId64 "\n", statsStartLegacy); + StringAppendF(&result, "statsEnd = %" PRId64 "\n", statsEndLegacy); + StringAppendF(&result, "totalFrames = %d\n", totalFramesLegacy); + StringAppendF(&result, "missedFrames = %d\n", missedFramesLegacy); + StringAppendF(&result, "clientCompositionFrames = %d\n", clientCompositionFramesLegacy); + StringAppendF(&result, "clientCompositionReusedFrames = %d\n", + clientCompositionReusedFramesLegacy); + StringAppendF(&result, "refreshRateSwitches = %d\n", refreshRateSwitchesLegacy); + StringAppendF(&result, "compositionStrategyChanges = %d\n", compositionStrategyChangesLegacy); + StringAppendF(&result, "displayOnTime = %" PRId64 " ms\n", displayOnTimeLegacy); StringAppendF(&result, "displayConfigStats is as below:\n"); - for (const auto& [fps, duration] : refreshRateStats) { + for (const auto& [fps, duration] : refreshRateStatsLegacy) { StringAppendF(&result, "%dfps = %ldms\n", fps, ns2ms(duration)); } result.back() = '\n'; - StringAppendF(&result, "totalP2PTime = %" PRId64 " ms\n", presentToPresent.totalTime()); + StringAppendF(&result, "totalP2PTime = %" PRId64 " ms\n", presentToPresentLegacy.totalTime()); StringAppendF(&result, "presentToPresent histogram is as below:\n"); - result.append(presentToPresent.toString()); - const float averageFrameDuration = frameDuration.averageTime(); + result.append(presentToPresentLegacy.toString()); + const float averageFrameDuration = frameDurationLegacy.averageTime(); StringAppendF(&result, "averageFrameDuration = %.3f ms\n", std::isnan(averageFrameDuration) ? 0.0f : averageFrameDuration); StringAppendF(&result, "frameDuration histogram is as below:\n"); - result.append(frameDuration.toString()); - const float averageRenderEngineTiming = renderEngineTiming.averageTime(); + result.append(frameDurationLegacy.toString()); + const float averageRenderEngineTiming = renderEngineTimingLegacy.averageTime(); StringAppendF(&result, "averageRenderEngineTiming = %.3f ms\n", std::isnan(averageRenderEngineTiming) ? 0.0f : averageRenderEngineTiming); StringAppendF(&result, "renderEngineTiming histogram is as below:\n"); - result.append(renderEngineTiming.toString()); + result.append(renderEngineTimingLegacy.toString()); + + result.append("\nGlobal aggregated jank payload (Timeline stats):"); + for (const auto& ele : stats) { + result.append("\n"); + StringAppendF(&result, "displayRefreshRate = %d fps\n", + ele.second.key.displayRefreshRateBucket); + StringAppendF(&result, "renderRate = %d fps\n", ele.second.key.renderRateBucket); + result.append(ele.second.jankPayload.toString()); + StringAppendF(&result, "sfDeadlineMisses histogram is as below:\n"); + result.append(ele.second.displayDeadlineDeltas.toString()); + StringAppendF(&result, "sfPredictionErrors histogram is as below:\n"); + result.append(ele.second.displayPresentDeltas.toString()); + } + const auto dumpStats = generateDumpStats(maxLayers); for (const auto& ele : dumpStats) { result.append(ele->toString()); @@ -173,30 +189,30 @@ SFTimeStatsLayerProto TimeStatsHelper::TimeStatsLayer::toProto() const { SFTimeStatsGlobalProto TimeStatsHelper::TimeStatsGlobal::toProto( std::optional<uint32_t> maxLayers) const { SFTimeStatsGlobalProto globalProto; - globalProto.set_stats_start(statsStart); - globalProto.set_stats_end(statsEnd); - globalProto.set_total_frames(totalFrames); - globalProto.set_missed_frames(missedFrames); - globalProto.set_client_composition_frames(clientCompositionFrames); - globalProto.set_display_on_time(displayOnTime); - for (const auto& ele : refreshRateStats) { + globalProto.set_stats_start(statsStartLegacy); + globalProto.set_stats_end(statsEndLegacy); + globalProto.set_total_frames(totalFramesLegacy); + globalProto.set_missed_frames(missedFramesLegacy); + globalProto.set_client_composition_frames(clientCompositionFramesLegacy); + globalProto.set_display_on_time(displayOnTimeLegacy); + for (const auto& ele : refreshRateStatsLegacy) { SFTimeStatsDisplayConfigBucketProto* configBucketProto = globalProto.add_display_config_stats(); SFTimeStatsDisplayConfigProto* configProto = configBucketProto->mutable_config(); configProto->set_fps(ele.first); configBucketProto->set_duration_millis(ns2ms(ele.second)); } - for (const auto& histEle : presentToPresent.hist) { + for (const auto& histEle : presentToPresentLegacy.hist) { SFTimeStatsHistogramBucketProto* histProto = globalProto.add_present_to_present(); histProto->set_time_millis(histEle.first); histProto->set_frame_count(histEle.second); } - for (const auto& histEle : frameDuration.hist) { + for (const auto& histEle : frameDurationLegacy.hist) { SFTimeStatsHistogramBucketProto* histProto = globalProto.add_frame_duration(); histProto->set_time_millis(histEle.first); histProto->set_frame_count(histEle.second); } - for (const auto& histEle : renderEngineTiming.hist) { + for (const auto& histEle : renderEngineTimingLegacy.hist) { SFTimeStatsHistogramBucketProto* histProto = globalProto.add_render_engine_timing(); histProto->set_time_millis(histEle.first); histProto->set_frame_count(histEle.second); @@ -212,8 +228,18 @@ SFTimeStatsGlobalProto TimeStatsHelper::TimeStatsGlobal::toProto( std::vector<TimeStatsHelper::TimeStatsLayer const*> TimeStatsHelper::TimeStatsGlobal::generateDumpStats(std::optional<uint32_t> maxLayers) const { std::vector<TimeStatsLayer const*> dumpStats; + + int numLayers = 0; + for (const auto& ele : stats) { + numLayers += ele.second.stats.size(); + } + + dumpStats.reserve(numLayers); + for (const auto& ele : stats) { - dumpStats.push_back(&ele.second); + for (const auto& layerEle : ele.second.stats) { + dumpStats.push_back(&layerEle.second); + } } std::sort(dumpStats.begin(), dumpStats.end(), diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h index 033eb5dcd9..38ee8882a6 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h +++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h @@ -57,6 +57,8 @@ public: uid_t uid; std::string layerName; std::string packageName; + int32_t displayRefreshRateBucket = 0; + int32_t renderRateBucket = 0; int32_t totalFrames = 0; int32_t droppedFrames = 0; int32_t lateAcquireFrames = 0; @@ -68,32 +70,84 @@ public: SFTimeStatsLayerProto toProto() const; }; - class TimeStatsGlobal { - public: - int64_t statsStart = 0; - int64_t statsEnd = 0; - int32_t totalFrames = 0; - int32_t missedFrames = 0; - int32_t clientCompositionFrames = 0; - int32_t clientCompositionReusedFrames = 0; - int32_t refreshRateSwitches = 0; - int32_t compositionStrategyChanges = 0; - int32_t displayEventConnectionsCount = 0; - int64_t displayOnTime = 0; - Histogram presentToPresent; - Histogram frameDuration; - Histogram renderEngineTiming; - - struct StatsHasher { - size_t operator()(const std::pair<uid_t, std::string>& p) const { - // Normally this isn't a very good hash function due to symmetry reasons, - // but these are distinct types so this should be good enough - return std::hash<uid_t>{}(p.first) ^ std::hash<std::string>{}(p.second); + // Lifted from SkiaGLRenderEngine's LinearEffect class. + // Which in turn was inspired by art/runtime/class_linker.cc + // Also this is what boost:hash_combine does so this is a pretty good hash. + static size_t HashCombine(size_t seed, size_t val) { + return seed ^ (val + 0x9e3779b9 + (seed << 6) + (seed >> 2)); + } + + struct TimelineStatsKey { + int32_t displayRefreshRateBucket = 0; + int32_t renderRateBucket = 0; + + struct Hasher { + size_t operator()(const TimelineStatsKey& key) const { + size_t result = std::hash<int32_t>{}(key.displayRefreshRateBucket); + return HashCombine(result, std::hash<int32_t>{}(key.renderRateBucket)); + } + }; + + bool operator==(const TimelineStatsKey& o) const { + return displayRefreshRateBucket == o.displayRefreshRateBucket && + renderRateBucket == o.renderRateBucket; + } + }; + + struct LayerStatsKey { + uid_t uid = 0; + std::string layerName; + + struct Hasher { + size_t operator()(const LayerStatsKey& key) const { + size_t result = std::hash<uid_t>{}(key.uid); + return HashCombine(result, std::hash<std::string>{}(key.layerName)); } }; - std::unordered_map<std::pair<uid_t, std::string>, TimeStatsLayer, StatsHasher> stats; - std::unordered_map<uint32_t, nsecs_t> refreshRateStats; + + bool operator==(const LayerStatsKey& o) const { + return uid == o.uid && layerName == o.layerName; + } + }; + + struct LayerStatsHasher { + size_t operator()(const std::pair<uid_t, std::string>& p) const { + // Normally this isn't a very good hash function due to symmetry reasons, + // but these are distinct types so this should be good enough + return std::hash<uid_t>{}(p.first) ^ std::hash<std::string>{}(p.second); + } + }; + + struct TimelineStats { + TimelineStatsKey key; JankPayload jankPayload; + Histogram displayDeadlineDeltas; + Histogram displayPresentDeltas; + std::unordered_map<LayerStatsKey, TimeStatsLayer, LayerStatsKey::Hasher> stats; + }; + + class TimeStatsGlobal { + public: + // Note: these are all legacy statistics, we're keeping these around because a variety of + // systems and form-factors find these useful when comparing with older releases. However, + // the current recommendation is that the new timeline-based metrics are used, and the old + // ones are deprecated. + int64_t statsStartLegacy = 0; + int64_t statsEndLegacy = 0; + int32_t totalFramesLegacy = 0; + int32_t missedFramesLegacy = 0; + int32_t clientCompositionFramesLegacy = 0; + int32_t clientCompositionReusedFramesLegacy = 0; + int32_t refreshRateSwitchesLegacy = 0; + int32_t compositionStrategyChangesLegacy = 0; + int32_t displayEventConnectionsCountLegacy = 0; + int64_t displayOnTimeLegacy = 0; + Histogram presentToPresentLegacy; + Histogram frameDurationLegacy; + Histogram renderEngineTimingLegacy; + std::unordered_map<uint32_t, nsecs_t> refreshRateStatsLegacy; + + std::unordered_map<TimelineStatsKey, TimelineStats, TimelineStatsKey::Hasher> stats; std::string toString(std::optional<uint32_t> maxLayers) const; SFTimeStatsGlobalProto toProto(std::optional<uint32_t> maxLayers) const; diff --git a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp index 6e9f09bdaa..b3ab8f15d6 100644 --- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp +++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp @@ -27,6 +27,7 @@ #include <cinttypes> using namespace std::chrono_literals; +using testing::_; using testing::AtLeast; using testing::Contains; using FrameTimelineEvent = perfetto::protos::FrameTimelineEvent; @@ -40,10 +41,6 @@ using ProtoFrameEnd = perfetto::protos::FrameTimelineEvent_FrameEnd; using ProtoPresentType = perfetto::protos::FrameTimelineEvent_PresentType; using ProtoJankType = perfetto::protos::FrameTimelineEvent_JankType; -MATCHER_P(HasBit, bit, "") { - return (arg & bit) != 0; -} - namespace android::frametimeline { class FrameTimelineTest : public testing::Test { @@ -238,7 +235,6 @@ TEST_F(FrameTimelineTest, createSurfaceFrameForToken_validInputEventId) { TEST_F(FrameTimelineTest, presentFenceSignaled_droppedFramesNotUpdated) { // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -249,14 +245,14 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_droppedFramesNotUpdated) { sLayerNameOne, sLayerNameOne); // Set up the display frame - mFrameTimeline->setSfWakeUp(token1, 20, 11); + mFrameTimeline->setSfWakeUp(token1, 20, Fps::fromPeriodNsecs(11)); 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, 11); + mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); auto& droppedSurfaceFrame = getSurfaceFrame(0, 0); @@ -265,10 +261,8 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_droppedFramesNotUpdated) { } TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)).Times(2); + 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}); @@ -280,7 +274,7 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { auto surfaceFrame2 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameTwo, sLayerNameTwo); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented); @@ -301,7 +295,7 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { auto surfaceFrame3 = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken2, 52, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(11)); surfaceFrame3->setPresentState(SurfaceFrame::PresentState::Dropped); mFrameTimeline->addSurfaceFrame(surfaceFrame3); mFrameTimeline->setSfPresent(56, presentFence2); @@ -318,11 +312,8 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { // Insert kMaxDisplayFrames' count of DisplayFrames to fill the deque int frameTimeFactor = 0; - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)) - .Times(static_cast<int32_t>(*maxDisplayFrames)); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)) + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)) .Times(static_cast<int32_t>(*maxDisplayFrames)); for (size_t i = 0; i < *maxDisplayFrames; i++) { auto presentFence = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -334,7 +325,7 @@ TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor, 11); + mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(27 + frameTimeFactor, presentFence); @@ -355,7 +346,7 @@ TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor, 11); + mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(27 + frameTimeFactor, presentFence); @@ -386,9 +377,6 @@ TEST_F(FrameTimelineTest, surfaceFrameEndTimeAcquireFenceBeforeQueue) { } TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)) - .Times(static_cast<int32_t>(*maxDisplayFrames + 10)); auto presentFence = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); presentFence->signalForTest(2); @@ -398,7 +386,7 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { mFrameTimeline->createSurfaceFrameForToken({}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); - mFrameTimeline->setSfWakeUp(sfToken, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken, 22, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(27, presentFence); @@ -408,16 +396,13 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { // Increase the size to 256 mFrameTimeline->setMaxDisplayFrames(256); EXPECT_EQ(*maxDisplayFrames, 256u); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)) - .Times(static_cast<int32_t>(*maxDisplayFrames + 10)); for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken({}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); - mFrameTimeline->setSfWakeUp(sfToken, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken, 22, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(27, presentFence); @@ -427,16 +412,13 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { // Shrink the size to 128 mFrameTimeline->setMaxDisplayFrames(128); EXPECT_EQ(*maxDisplayFrames, 128u); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)) - .Times(static_cast<int32_t>(*maxDisplayFrames + 10)); for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken({}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); - mFrameTimeline->setSfWakeUp(sfToken, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken, 22, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(27, presentFence); @@ -446,11 +428,19 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { // Tests related to TimeStats TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) { + Fps refreshRate = Fps(11); EXPECT_CALL(*mTimeStats, - incrementJankyFrames(sUidOne, sLayerNameOne, - HasBit(JankType::SurfaceFlingerCpuDeadlineMissed))); - EXPECT_CALL(*mTimeStats, - incrementJankyFrames(HasBit(JankType::SurfaceFlingerCpuDeadlineMissed))); + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, + JankType::SurfaceFlingerCpuDeadlineMissed, + std::chrono::duration_cast< + std::chrono::nanoseconds>(3ms) + .count(), + std::chrono::duration_cast< + std::chrono::nanoseconds>(10ms) + .count(), + 0})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), @@ -465,7 +455,9 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) { sUidOne, sLayerNameOne, sLayerNameOne); mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - 11); + refreshRate); + surfaceFrame1->setAcquireFenceTime( + std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count()); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); presentFence1->signalForTest( @@ -476,9 +468,11 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) { } TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { + Fps refreshRate = Fps::fromPeriodNsecs(30); EXPECT_CALL(*mTimeStats, - incrementJankyFrames(sUidOne, sLayerNameOne, HasBit(JankType::DisplayHAL))); - EXPECT_CALL(*mTimeStats, incrementJankyFrames(HasBit(JankType::DisplayHAL))); + incrementJankyFrames(TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, JankType::DisplayHAL, + 0, 0, 0})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( @@ -494,8 +488,10 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { sUidOne, sLayerNameOne, sLayerNameOne); mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - 30); + refreshRate); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); + surfaceFrame1->setAcquireFenceTime( + std::chrono::duration_cast<std::chrono::nanoseconds>(20ms).count()); mFrameTimeline->addSurfaceFrame(surfaceFrame1); presentFence1->signalForTest( std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); @@ -505,10 +501,14 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { } TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { + Fps refreshRate = Fps(11.0); EXPECT_CALL(*mTimeStats, - incrementJankyFrames(sUidOne, sLayerNameOne, - HasBit(JankType::AppDeadlineMissed))); - EXPECT_CALL(*mTimeStats, incrementJankyFrames(HasBit(JankType::AppDeadlineMissed))); + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, std::nullopt, sUidOne, + sLayerNameOne, JankType::AppDeadlineMissed, 0, 0, + std::chrono::duration_cast< + std::chrono::nanoseconds>(25ms) + .count()})); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions( {std::chrono::duration_cast<std::chrono::nanoseconds>(10ms).count(), @@ -525,7 +525,7 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { std::chrono::duration_cast<std::chrono::nanoseconds>(45ms).count()); mFrameTimeline->setSfWakeUp(sfToken1, std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count(), - 11); + refreshRate); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); @@ -537,6 +537,45 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { EXPECT_EQ(surfaceFrame1->getJankType(), JankType::AppDeadlineMissed); } +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMissWithRenderRate) { + Fps refreshRate = Fps(11.0); + Fps renderRate = Fps(30.0); + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{refreshRate, renderRate, sUidOne, sLayerNameOne, + JankType::AppDeadlineMissed, 0, 0, + std::chrono::duration_cast< + std::chrono::nanoseconds>(25ms) + .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()}); + 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()}); + 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->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); + + EXPECT_EQ(surfaceFrame1->getJankType(), JankType::AppDeadlineMissed); +} + /* * Tracing Tests * @@ -547,8 +586,6 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { */ TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -559,7 +596,7 @@ TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) { sLayerNameOne, sLayerNameOne); // Set up the display frame - mFrameTimeline->setSfWakeUp(token1, 20, 11); + mFrameTimeline->setSfWakeUp(token1, 20, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Dropped); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(25, presentFence1); @@ -567,7 +604,7 @@ TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) { // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the // next frame - mFrameTimeline->setSfWakeUp(token2, 50, 11); + mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); auto packets = readFrameTimelinePacketsBlocking(tracingSession.get()); @@ -576,10 +613,8 @@ TEST_F(FrameTimelineTest, tracing_noPacketsSentWithoutTraceStart) { TEST_F(FrameTimelineTest, tracing_sanityTest) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -591,7 +626,7 @@ TEST_F(FrameTimelineTest, tracing_sanityTest) { sLayerNameOne, sLayerNameOne); // Set up the display frame - mFrameTimeline->setSfWakeUp(token2, 20, 11); + mFrameTimeline->setSfWakeUp(token2, 20, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(25, presentFence1); @@ -599,7 +634,7 @@ TEST_F(FrameTimelineTest, tracing_sanityTest) { // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the // next frame - mFrameTimeline->setSfWakeUp(token2, 50, 11); + mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); presentFence2->signalForTest(55); @@ -613,8 +648,6 @@ TEST_F(FrameTimelineTest, tracing_sanityTest) { TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -622,13 +655,13 @@ TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30}); // Set up the display frame - mFrameTimeline->setSfWakeUp(-1, 20, 11); + 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, 11); + mFrameTimeline->setSfWakeUp(token1, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); presentFence2->signalForTest(60); @@ -641,8 +674,6 @@ TEST_F(FrameTimelineTest, traceDisplayFrame_invalidTokenDoesNotEmitTracePacket) TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -653,7 +684,7 @@ TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) sLayerNameOne, sLayerNameOne); // Set up the display frame - mFrameTimeline->setSfWakeUp(token1, 20, 11); + mFrameTimeline->setSfWakeUp(token1, 20, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Dropped); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(25, presentFence1); @@ -661,7 +692,7 @@ TEST_F(FrameTimelineTest, traceSurfaceFrame_invalidTokenDoesNotEmitTracePacket) // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the // next frame - mFrameTimeline->setSfWakeUp(token2, 50, 11); + mFrameTimeline->setSfWakeUp(token2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); presentFence2->signalForTest(60); @@ -759,8 +790,6 @@ void validateTraceEvent(const ProtoFrameEnd& received, const ProtoFrameEnd& sour TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -769,7 +798,7 @@ TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) { int64_t displayFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60}); // Set up the display frame - mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, 11); + mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(26, presentFence1); presentFence1->signalForTest(31); @@ -797,7 +826,7 @@ TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) { // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the // next frame - mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, 11); + mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); presentFence2->signalForTest(55); @@ -854,10 +883,8 @@ TEST_F(FrameTimelineTest, traceDisplayFrame_emitsValidTracePacket) { TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) { auto tracingSession = getTracingSessionForTest(); - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); @@ -902,7 +929,7 @@ TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) { protoActualSurfaceFrameEnd.set_cookie(traceCookie + 2); // Set up the display frame - mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, 11); + mFrameTimeline->setSfWakeUp(displayFrameToken1, 20, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(26, presentFence1); @@ -910,7 +937,7 @@ TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) { // Trigger a flushPresentFence (which will call trace function) by calling setSfPresent for the // next frame - mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, 11); + mFrameTimeline->setSfWakeUp(displayFrameToken2, 50, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(55, presentFence2); presentFence2->signalForTest(55); @@ -967,17 +994,15 @@ TEST_F(FrameTimelineTest, traceSurfaceFrame_emitsValidTracePacket) { // Tests for Jank classification TEST_F(FrameTimelineTest, jankClassification_presentOnTimeDoesNotClassify) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t surfaceFrameToken = mTokenManager->generateTokenForPredictions({10, 20, 30}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 30}); auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, Fps::fromPeriodNsecs(11)); surfaceFrame->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame); mFrameTimeline->setSfPresent(26, presentFence1); @@ -1001,12 +1026,11 @@ TEST_F(FrameTimelineTest, jankClassification_presentOnTimeDoesNotClassify) { } TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishEarlyPresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); + Fps vsyncRate = Fps::fromPeriodNsecs(11); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 70}); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, vsyncRate); mFrameTimeline->setSfPresent(26, presentFence1); auto displayFrame = getDisplayFrame(0); presentFence1->signalForTest(30); @@ -1016,7 +1040,7 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishEarlyPresen // Trigger a flush by finalizing the next DisplayFrame auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); - mFrameTimeline->setSfWakeUp(sfToken2, 52, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 52, vsyncRate); mFrameTimeline->setSfPresent(56, presentFence2); displayFrame = getDisplayFrame(0); @@ -1030,7 +1054,6 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishEarlyPresen auto displayFrame2 = getDisplayFrame(1); presentFence2->signalForTest(65); EXPECT_EQ(displayFrame2->getActuals().presentTime, 0); - addEmptyDisplayFrame(); displayFrame2 = getDisplayFrame(1); @@ -1042,12 +1065,11 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishEarlyPresen } TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishLatePresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); + Fps vsyncRate = Fps::fromPeriodNsecs(11); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 70}); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, vsyncRate); mFrameTimeline->setSfPresent(26, presentFence1); auto displayFrame = getDisplayFrame(0); presentFence1->signalForTest(50); @@ -1057,7 +1079,7 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishLatePresent // Trigger a flush by finalizing the next DisplayFrame auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); - mFrameTimeline->setSfWakeUp(sfToken2, 52, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 52, vsyncRate); mFrameTimeline->setSfPresent(56, presentFence2); displayFrame = getDisplayFrame(0); @@ -1083,11 +1105,9 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameOnTimeFinishLatePresent } TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishEarlyPresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({12, 18, 40}); - mFrameTimeline->setSfWakeUp(sfToken1, 12, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 12, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(22, presentFence1); auto displayFrame = getDisplayFrame(0); @@ -1107,11 +1127,9 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishEarlyPresent) } TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishLatePresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40}); - mFrameTimeline->setSfWakeUp(sfToken1, 12, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 12, Fps::fromPeriodNsecs(11)); mFrameTimeline->setSfPresent(36, presentFence1); auto displayFrame = getDisplayFrame(0); presentFence1->signalForTest(52); @@ -1130,10 +1148,7 @@ TEST_F(FrameTimelineTest, jankClassification_displayFrameLateFinishLatePresent) } TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); - // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)).Times(2); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 70}); @@ -1143,7 +1158,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresen mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame1->setAcquireFenceTime(16); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(26, presentFence1); @@ -1162,7 +1177,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresen mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame2->setAcquireFenceTime(36); - mFrameTimeline->setSfWakeUp(sfToken2, 52, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(11)); surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame2); mFrameTimeline->setSfPresent(56, presentFence2); @@ -1187,6 +1202,14 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresen auto actuals2 = presentedSurfaceFrame2.getActuals(); EXPECT_EQ(actuals2.presentTime, 0); + ::testing::Mock::VerifyAndClearExpectations(mTimeStats.get()); + + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{Fps::fromPeriodNsecs(11), std::nullopt, sUidOne, + sLayerNameOne, JankType::PredictionError, 0, 5, + 0})); + addEmptyDisplayFrame(); // Fences for the second frame have flushed, so the present timestamps should be updated @@ -1203,10 +1226,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishEarlyPresen } TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishLatePresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); - // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)).Times(2); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 40}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 70}); @@ -1216,7 +1236,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishLatePresent mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame1->setAcquireFenceTime(16); - mFrameTimeline->setSfWakeUp(sfToken1, 22, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 22, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(26, presentFence1); @@ -1235,7 +1255,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishLatePresent mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame2->setAcquireFenceTime(36); - mFrameTimeline->setSfWakeUp(sfToken2, 52, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 52, Fps::fromPeriodNsecs(11)); surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame2); mFrameTimeline->setSfPresent(56, presentFence2); @@ -1260,6 +1280,14 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishLatePresent auto actuals2 = presentedSurfaceFrame2.getActuals(); EXPECT_EQ(actuals2.presentTime, 0); + ::testing::Mock::VerifyAndClearExpectations(mTimeStats.get()); + + EXPECT_CALL(*mTimeStats, + incrementJankyFrames( + TimeStats::JankyFramesInfo{Fps::fromPeriodNsecs(11), std::nullopt, sUidOne, + sLayerNameOne, JankType::PredictionError, 0, 5, + 0})); + addEmptyDisplayFrame(); // Fences for the second frame have flushed, so the present timestamps should be updated @@ -1276,10 +1304,8 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameOnTimeFinishLatePresent } TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishEarlyPresent) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)); - // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)); + auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({42, 46, 50}); int64_t surfaceFrameToken1 = mTokenManager->generateTokenForPredictions({5, 26, 60}); @@ -1287,7 +1313,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishEarlyPresent) mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame1->setAcquireFenceTime(40); - mFrameTimeline->setSfWakeUp(sfToken1, 42, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 42, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(46, presentFence1); @@ -1320,10 +1346,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishLatePresent) // AppDeadlineMissed. Second frame - DisplayFrame is janky. This should propagate DisplayFrame's // jank to the SurfaceFrame. - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); - // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)).Times(2); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(_)).Times(2); auto presentFence1 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({32, 36, 40}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({42, 46, 50}); @@ -1333,7 +1356,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishLatePresent) mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame1->setAcquireFenceTime(26); - mFrameTimeline->setSfWakeUp(sfToken1, 32, 11); + mFrameTimeline->setSfWakeUp(sfToken1, 32, Fps::fromPeriodNsecs(11)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(36, presentFence1); @@ -1352,7 +1375,7 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishLatePresent) mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame2->setAcquireFenceTime(40); - mFrameTimeline->setSfWakeUp(sfToken2, 43, 11); + mFrameTimeline->setSfWakeUp(sfToken2, 43, Fps::fromPeriodNsecs(11)); surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame2); mFrameTimeline->setSfPresent(56, presentFence2); @@ -1393,10 +1416,8 @@ TEST_F(FrameTimelineTest, jankClassification_surfaceFrameLateFinishLatePresent) } TEST_F(FrameTimelineTest, jankClassification_multiJankBufferStuffingAndAppDeadlineMissed) { - // Global increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_)).Times(2); // Layer specific increment - EXPECT_CALL(*mTimeStats, incrementJankyFrames(testing::_, testing::_, testing::_)).Times(2); + 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}); @@ -1407,7 +1428,7 @@ TEST_F(FrameTimelineTest, jankClassification_multiJankBufferStuffingAndAppDeadli mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken1, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame1->setAcquireFenceTime(50); - mFrameTimeline->setSfWakeUp(sfToken1, 52, 30); + mFrameTimeline->setSfWakeUp(sfToken1, 52, Fps::fromPeriodNsecs(30)); surfaceFrame1->setPresentState(SurfaceFrame::PresentState::Presented); mFrameTimeline->addSurfaceFrame(surfaceFrame1); mFrameTimeline->setSfPresent(56, presentFence1); @@ -1426,7 +1447,7 @@ TEST_F(FrameTimelineTest, jankClassification_multiJankBufferStuffingAndAppDeadli mFrameTimeline->createSurfaceFrameForToken({surfaceFrameToken2, sInputEventId}, sPidOne, sUidOne, sLayerNameOne, sLayerNameOne); surfaceFrame2->setAcquireFenceTime(84); - mFrameTimeline->setSfWakeUp(sfToken2, 112, 30); + mFrameTimeline->setSfWakeUp(sfToken2, 112, Fps::fromPeriodNsecs(30)); surfaceFrame2->setPresentState(SurfaceFrame::PresentState::Presented, 54); mFrameTimeline->addSurfaceFrame(surfaceFrame2); mFrameTimeline->setSfPresent(116, presentFence2); diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp index df4464ef52..35c32ec033 100644 --- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp +++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp @@ -55,14 +55,21 @@ using testing::UnorderedElementsAre; using PowerMode = hardware::graphics::composer::V2_4::IComposerClient::PowerMode; // clang-format off -#define FMT_PROTO true -#define FMT_STRING false -#define LAYER_ID_0 0 -#define LAYER_ID_1 1 -#define UID_0 123 -#define LAYER_ID_INVALID -1 -#define NUM_LAYERS 1 -#define NUM_LAYERS_INVALID "INVALID" +#define FMT_PROTO true +#define FMT_STRING false +#define LAYER_ID_0 0 +#define LAYER_ID_1 1 +#define UID_0 123 +#define REFRESH_RATE_0 61 +#define RENDER_RATE_0 31 +#define REFRESH_RATE_BUCKET_0 60 +#define RENDER_RATE_BUCKET_0 30 +#define LAYER_ID_INVALID -1 +#define NUM_LAYERS 1 +#define NUM_LAYERS_INVALID "INVALID" + +const constexpr Fps kRefreshRate0 = Fps(static_cast<float>(REFRESH_RATE_0)); +const constexpr Fps kRenderRate0 = Fps(static_cast<float>(RENDER_RATE_0)); enum InputCommand : int32_t { ENABLE = 0, @@ -246,11 +253,13 @@ void TimeStatsTest::setTimeStamp(TimeStamp type, int32_t id, uint64_t frameNumbe ASSERT_NO_FATAL_FAILURE(mTimeStats->setDesiredTime(id, frameNumber, ts)); break; case TimeStamp::PRESENT: - ASSERT_NO_FATAL_FAILURE(mTimeStats->setPresentTime(id, frameNumber, ts)); + ASSERT_NO_FATAL_FAILURE( + mTimeStats->setPresentTime(id, frameNumber, ts, kRefreshRate0, kRenderRate0)); break; case TimeStamp::PRESENT_FENCE: - ASSERT_NO_FATAL_FAILURE( - mTimeStats->setPresentFence(id, frameNumber, std::make_shared<FenceTime>(ts))); + ASSERT_NO_FATAL_FAILURE(mTimeStats->setPresentFence(id, frameNumber, + std::make_shared<FenceTime>(ts), + kRefreshRate0, kRenderRate0)); break; default: ALOGD("Invalid timestamp type"); @@ -352,48 +361,29 @@ TEST_F(TimeStatsTest, canIncreaseBadDesiredPresent) { EXPECT_THAT(result, HasSubstr(expectedResult)); } -TEST_F(TimeStatsTest, canIncreaseJankyFrames) { +TEST_F(TimeStatsTest, canIncreaseJankyFramesForLayer) { // this stat is not in the proto so verify by checking the string dump EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000); - mTimeStats->incrementJankyFrames(JankType::SurfaceFlingerCpuDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::SurfaceFlingerGpuDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::DisplayHAL); - mTimeStats->incrementJankyFrames(JankType::AppDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::None); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerCpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerGpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::DisplayHAL, 1, 2, 3}); + 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::None, 1, 2, 3}); const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); - std::string expectedResult = "totalTimelineFrames = " + std::to_string(5); - EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "jankyFrames = " + std::to_string(4); + std::string expectedResult = + "displayRefreshRate = " + std::to_string(REFRESH_RATE_BUCKET_0) + " fps"; EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "sfLongCpuJankyFrames = " + std::to_string(1); + expectedResult = "renderRate = " + std::to_string(RENDER_RATE_BUCKET_0) + " fps"; EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "sfLongGpuJankyFrames = " + std::to_string(1); - EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "sfUnattributedJankyFrame = " + std::to_string(1); - EXPECT_THAT(result, HasSubstr(expectedResult)); - expectedResult = "appUnattributedJankyFrame = " + std::to_string(1); - EXPECT_THAT(result, HasSubstr(expectedResult)); -} - -TEST_F(TimeStatsTest, canIncreaseJankyFramesForLayer) { - // this stat is not in the proto so verify by checking the string dump - EXPECT_TRUE(inputCommand(InputCommand::ENABLE, FMT_STRING).empty()); - - insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerCpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerGpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::DisplayHAL); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::AppDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::None); - - const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); - std::string expectedResult = "totalTimelineFrames = " + std::to_string(5); + expectedResult = "totalTimelineFrames = " + std::to_string(5); EXPECT_THAT(result, HasSubstr(expectedResult)); expectedResult = "jankyFrames = " + std::to_string(4); EXPECT_THAT(result, HasSubstr(expectedResult)); @@ -848,14 +838,16 @@ TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) { mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>( std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count())); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerCpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerGpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::DisplayHAL); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::AppDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::None); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerCpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerGpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::DisplayHAL, 1, 2, 3}); + 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::None, 1, 2, 3}); EXPECT_TRUE(inputCommand(InputCommand::CLEAR, FMT_STRING).empty()); @@ -865,11 +857,6 @@ TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) { EXPECT_THAT(result, HasSubstr("compositionStrategyChanges = 0")); EXPECT_THAT(result, HasSubstr("averageFrameDuration = 0.000 ms")); EXPECT_THAT(result, HasSubstr("averageRenderEngineTiming = 0.000 ms")); - EXPECT_THAT(result, HasSubstr("jankyFrames = 0")); - EXPECT_THAT(result, HasSubstr("sfLongCpuJankyFrames = 0")); - EXPECT_THAT(result, HasSubstr("sfLongGpuJankyFrames = 0")); - EXPECT_THAT(result, HasSubstr("sfUnattributedJankyFrame = 0")); - EXPECT_THAT(result, HasSubstr("appUnattributedJankyFrame = 0")); } TEST_F(TimeStatsTest, canDumpWithMaxLayers) { @@ -1000,11 +987,16 @@ TEST_F(TimeStatsTest, globalStatsCallback) { mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(3000000)); mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(5000000)); - mTimeStats->incrementJankyFrames(JankType::SurfaceFlingerCpuDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::SurfaceFlingerGpuDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::DisplayHAL); - mTimeStats->incrementJankyFrames(JankType::AppDeadlineMissed); - mTimeStats->incrementJankyFrames(JankType::None); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerCpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerGpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::DisplayHAL, 1, 2, 3}); + 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::None, 1, 2, 3}); EXPECT_THAT(mDelegate->mAtomTags, UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO, @@ -1015,6 +1007,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}); { InSequence seq; @@ -1047,18 +1041,20 @@ TEST_F(TimeStatsTest, globalStatsCallback) { 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, 0)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, REFRESH_RATE_BUCKET_0)); EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, - BytesEq((const uint8_t*)expectedEmptyHistogram.c_str(), - expectedEmptyHistogram.size()), - expectedEmptyHistogram.size())); + BytesEq((const uint8_t*) + expectedSfDeadlineMissed.c_str(), + expectedSfDeadlineMissed.size()), + expectedSfDeadlineMissed.size())); EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, - BytesEq((const uint8_t*)expectedEmptyHistogram.c_str(), - expectedEmptyHistogram.size()), - expectedEmptyHistogram.size())); - EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 0)); + BytesEq((const uint8_t*) + expectedSfPredictionErrors.c_str(), + expectedSfPredictionErrors.size()), + expectedSfPredictionErrors.size())); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, RENDER_RATE_BUCKET_0)); EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent)); } @@ -1091,14 +1087,16 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { } insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerCpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::SurfaceFlingerGpuDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::DisplayHAL); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), - JankType::AppDeadlineMissed); - mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), JankType::None); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerCpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::SurfaceFlingerGpuDeadlineMissed, 1, 2, 3}); + mTimeStats->incrementJankyFrames({kRefreshRate0, kRenderRate0, UID_0, genLayerName(LAYER_ID_0), + JankType::DisplayHAL, 1, 2, 3}); + 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::None, 1, 2, 3}); EXPECT_THAT(mDelegate->mAtomTags, UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO, @@ -1113,7 +1111,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 expectedEmptyHistogram = buildExpectedHistogramBytestring({}, {}); + std::string expectedAppDeadlineMissed = buildExpectedHistogramBytestring({3}, {4}); { InSequence seq; EXPECT_CALL(*mDelegate, @@ -1170,8 +1168,8 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { 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, 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, statsEventWriteByteArray(mDelegate->mEvent, BytesEq((const uint8_t*) @@ -1180,9 +1178,10 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { expectedFrameRateOverride.size())); EXPECT_CALL(*mDelegate, statsEventWriteByteArray(mDelegate->mEvent, - BytesEq((const uint8_t*)expectedEmptyHistogram.c_str(), - expectedEmptyHistogram.size()), - expectedEmptyHistogram.size())); + BytesEq((const uint8_t*) + expectedAppDeadlineMissed.c_str(), + expectedAppDeadlineMissed.size()), + expectedAppDeadlineMissed.size())); EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent)); } diff --git a/services/surfaceflinger/tests/unittests/mock/MockFrameTimeline.h b/services/surfaceflinger/tests/unittests/mock/MockFrameTimeline.h index 0a6a9f4550..44b9b73fd4 100644 --- a/services/surfaceflinger/tests/unittests/mock/MockFrameTimeline.h +++ b/services/surfaceflinger/tests/unittests/mock/MockFrameTimeline.h @@ -31,7 +31,7 @@ public: MOCK_METHOD0(onBootFinished, void()); MOCK_METHOD1(addSurfaceFrame, void(std::shared_ptr<frametimeline::SurfaceFrame>)); - MOCK_METHOD3(setSfWakeUp, void(int64_t, nsecs_t, nsecs_t)); + MOCK_METHOD3(setSfWakeUp, void(int64_t, nsecs_t, Fps)); MOCK_METHOD2(setSfPresent, void(nsecs_t, const std::shared_ptr<FenceTime>&)); }; diff --git a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h index 99ec353095..3e4a0b8c09 100644 --- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h +++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h @@ -48,10 +48,11 @@ public: MOCK_METHOD3(setDesiredTime, void(int32_t, uint64_t, nsecs_t)); MOCK_METHOD3(setAcquireTime, void(int32_t, uint64_t, nsecs_t)); MOCK_METHOD3(setAcquireFence, void(int32_t, uint64_t, const std::shared_ptr<FenceTime>&)); - MOCK_METHOD3(setPresentTime, void(int32_t, uint64_t, nsecs_t)); - MOCK_METHOD3(setPresentFence, void(int32_t, uint64_t, const std::shared_ptr<FenceTime>&)); - MOCK_METHOD1(incrementJankyFrames, void(int32_t)); - MOCK_METHOD3(incrementJankyFrames, void(uid_t, const std::string&, int32_t)); + MOCK_METHOD5(setPresentTime, void(int32_t, uint64_t, nsecs_t, Fps, std::optional<Fps>)); + MOCK_METHOD5(setPresentFence, + void(int32_t, uint64_t, const std::shared_ptr<FenceTime>&, Fps, + std::optional<Fps>)); + MOCK_METHOD1(incrementJankyFrames, void(const JankyFramesInfo&)); MOCK_METHOD1(onDestroy, void(int32_t)); MOCK_METHOD2(removeTimeRecord, void(int32_t, uint64_t)); MOCK_METHOD1(setPowerMode, |