diff options
15 files changed, 509 insertions, 108 deletions
diff --git a/services/surfaceflinger/BufferQueueLayer.cpp b/services/surfaceflinger/BufferQueueLayer.cpp index 0863a22659..51c7ed5b53 100644 --- a/services/surfaceflinger/BufferQueueLayer.cpp +++ b/services/surfaceflinger/BufferQueueLayer.cpp @@ -442,7 +442,8 @@ void BufferQueueLayer::onFrameAvailable(const BufferItem& item) { } auto surfaceFrame = - mFlinger->mFrameTimeline->createSurfaceFrameForToken(mName, mFrameTimelineVsyncId); + mFlinger->mFrameTimeline->createSurfaceFrameForToken(mOwnerUid, mName, mName, + mFrameTimelineVsyncId); surfaceFrame->setActualQueueTime(systemTime()); mQueueItems.push_back({item, std::move(surfaceFrame)}); @@ -480,7 +481,8 @@ void BufferQueueLayer::onFrameReplaced(const BufferItem& item) { } auto surfaceFrame = - mFlinger->mFrameTimeline->createSurfaceFrameForToken(mName, mFrameTimelineVsyncId); + mFlinger->mFrameTimeline->createSurfaceFrameForToken(mOwnerUid, mName, mName, + mFrameTimelineVsyncId); surfaceFrame->setActualQueueTime(systemTime()); mQueueItems[mQueueItems.size() - 1].item = item; mQueueItems[mQueueItems.size() - 1].surfaceFrame = std::move(surfaceFrame); diff --git a/services/surfaceflinger/BufferStateLayer.cpp b/services/surfaceflinger/BufferStateLayer.cpp index 361c1f3f98..66b4e197ec 100644 --- a/services/surfaceflinger/BufferStateLayer.cpp +++ b/services/surfaceflinger/BufferStateLayer.cpp @@ -276,7 +276,7 @@ bool BufferStateLayer::setBuffer(const sp<GraphicBuffer>& buffer, const sp<Fence const int32_t layerId = getSequence(); mFlinger->mTimeStats->setPostTime(layerId, mCurrentState.frameNumber, getName().c_str(), - postTime); + mOwnerUid, postTime); desiredPresentTime = desiredPresentTime <= 0 ? 0 : desiredPresentTime; mCurrentState.desiredPresentTime = desiredPresentTime; diff --git a/services/surfaceflinger/FrameTimeline/Android.bp b/services/surfaceflinger/FrameTimeline/Android.bp index 6ba4c432c6..e075d3e1a0 100644 --- a/services/surfaceflinger/FrameTimeline/Android.bp +++ b/services/surfaceflinger/FrameTimeline/Android.bp @@ -5,10 +5,12 @@ cc_library_static { "FrameTimeline.cpp", ], shared_libs: [ + "android.hardware.graphics.composer@2.4", "libbase", "libcutils", "liblog", "libgui", + "libtimestats", "libui", "libutils", ], diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp index 43176a3f10..996479c1c7 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp @@ -93,19 +93,19 @@ std::string toString(PredictionState predictionState) { } } -std::string toString(JankType jankType) { +std::string toString(TimeStats::JankType jankType) { switch (jankType) { - case JankType::None: + case TimeStats::JankType::None: return "None"; - case JankType::Display: + case TimeStats::JankType::Display: return "Composer/Display - outside SF and App"; - case JankType::SurfaceFlingerDeadlineMissed: + case TimeStats::JankType::SurfaceFlingerDeadlineMissed: return "SurfaceFlinger Deadline Missed"; - case JankType::AppDeadlineMissed: + case TimeStats::JankType::AppDeadlineMissed: return "App Deadline Missed"; - case JankType::PredictionExpired: + case TimeStats::JankType::PredictionExpired: return "Prediction Expired"; - case JankType::SurfaceFlingerEarlyLatch: + case TimeStats::JankType::SurfaceFlingerEarlyLatch: return "SurfaceFlinger Early Latch"; default: return "Unclassified"; @@ -177,15 +177,18 @@ void TokenManager::flushTokens(nsecs_t flushTime) { } } -SurfaceFrame::SurfaceFrame(const std::string& layerName, PredictionState predictionState, +SurfaceFrame::SurfaceFrame(uid_t ownerUid, std::string layerName, std::string debugName, + PredictionState predictionState, frametimeline::TimelineItem&& predictions) - : mLayerName(layerName), + : mOwnerUid(ownerUid), + mLayerName(std::move(layerName)), + mDebugName(std::move(debugName)), mPresentState(PresentState::Unknown), mPredictionState(predictionState), mPredictions(predictions), mActuals({0, 0, 0}), mActualQueueTime(0), - mJankType(JankType::None), + mJankType(TimeStats::JankType::None), mJankMetadata(0) {} void SurfaceFrame::setPresentState(PresentState state) { @@ -227,17 +230,25 @@ void SurfaceFrame::setActualPresentTime(nsecs_t presentTime) { mActuals.presentTime = presentTime; } -void SurfaceFrame::setJankInfo(JankType jankType, int32_t jankMetadata) { +void SurfaceFrame::setJankInfo(TimeStats::JankType jankType, int32_t jankMetadata) { std::lock_guard<std::mutex> lock(mMutex); mJankType = jankType; mJankMetadata = jankMetadata; } -JankType SurfaceFrame::getJankType() const { +TimeStats::JankType SurfaceFrame::getJankType() const { std::lock_guard<std::mutex> lock(mMutex); return mJankType; } +uid_t SurfaceFrame::getOwnerUid() const { + return mOwnerUid; +} + +const std::string& SurfaceFrame::getName() const { + return mLayerName; +} + nsecs_t SurfaceFrame::getBaseTime() const { std::lock_guard<std::mutex> lock(mMutex); nsecs_t baseTime = std::numeric_limits<nsecs_t>::max(); @@ -267,8 +278,8 @@ std::string presentStateToString(SurfaceFrame::PresentState presentState) { void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t baseTime) { std::lock_guard<std::mutex> lock(mMutex); StringAppendF(&result, "%s", indent.c_str()); - StringAppendF(&result, "Layer - %s", mLayerName.c_str()); - if (mJankType != JankType::None) { + StringAppendF(&result, "Layer - %s", mDebugName.c_str()); + if (mJankType != TimeStats::JankType::None) { // Easily identify a janky Surface Frame in the dump StringAppendF(&result, " [*] "); } @@ -285,33 +296,35 @@ void SurfaceFrame::dump(std::string& result, const std::string& indent, nsecs_t dumpTable(result, mPredictions, mActuals, indent, mPredictionState, baseTime); } -FrameTimeline::FrameTimeline() +FrameTimeline::FrameTimeline(std::shared_ptr<TimeStats> timeStats) : mCurrentDisplayFrame(std::make_shared<DisplayFrame>()), - mMaxDisplayFrames(kDefaultMaxDisplayFrames) {} + mMaxDisplayFrames(kDefaultMaxDisplayFrames), + mTimeStats(std::move(timeStats)) {} FrameTimeline::DisplayFrame::DisplayFrame() : surfaceFlingerPredictions(TimelineItem()), surfaceFlingerActuals(TimelineItem()), predictionState(PredictionState::None), - jankType(JankType::None), + jankType(TimeStats::JankType::None), jankMetadata(0) { this->surfaceFrames.reserve(kNumSurfaceFramesInitial); } std::unique_ptr<android::frametimeline::SurfaceFrame> FrameTimeline::createSurfaceFrameForToken( - const std::string& layerName, std::optional<int64_t> token) { + uid_t uid, std::string layerName, std::string debugName, std::optional<int64_t> token) { ATRACE_CALL(); if (!token) { - return std::make_unique<impl::SurfaceFrame>(layerName, PredictionState::None, - TimelineItem()); + return std::make_unique<impl::SurfaceFrame>(uid, std::move(layerName), std::move(debugName), + PredictionState::None, TimelineItem()); } std::optional<TimelineItem> predictions = mTokenManager.getPredictionsForToken(*token); if (predictions) { - return std::make_unique<impl::SurfaceFrame>(layerName, PredictionState::Valid, + return std::make_unique<impl::SurfaceFrame>(uid, std::move(layerName), std::move(debugName), + PredictionState::Valid, std::move(*predictions)); } - return std::make_unique<impl::SurfaceFrame>(layerName, PredictionState::Expired, - TimelineItem()); + return std::make_unique<impl::SurfaceFrame>(uid, std::move(layerName), std::move(debugName), + PredictionState::Expired, TimelineItem()); } void FrameTimeline::addSurfaceFrame( @@ -359,6 +372,7 @@ void FrameTimeline::flushPendingPresentFences() { } } if (signalTime != Fence::SIGNAL_TIME_INVALID) { + int32_t totalJankReasons = TimeStats::JankType::None; auto& displayFrame = pendingPresentFence.second; displayFrame->surfaceFlingerActuals.presentTime = signalTime; @@ -377,21 +391,26 @@ void FrameTimeline::flushPendingPresentFences() { displayFrame->jankMetadata |= EarlyFinish; } - if (displayFrame->jankMetadata & EarlyFinish & EarlyPresent) { - displayFrame->jankType = JankType::SurfaceFlingerEarlyLatch; - } else if (displayFrame->jankMetadata & LateFinish & LatePresent) { - displayFrame->jankType = JankType::SurfaceFlingerDeadlineMissed; + if ((displayFrame->jankMetadata & EarlyFinish) && + (displayFrame->jankMetadata & EarlyPresent)) { + displayFrame->jankType = TimeStats::JankType::SurfaceFlingerEarlyLatch; + } else if ((displayFrame->jankMetadata & LateFinish) && + (displayFrame->jankMetadata & LatePresent)) { + displayFrame->jankType = TimeStats::JankType::SurfaceFlingerDeadlineMissed; } else if (displayFrame->jankMetadata & EarlyPresent || displayFrame->jankMetadata & LatePresent) { // Cases where SF finished early but frame was presented late and vice versa - displayFrame->jankType = JankType::Display; + displayFrame->jankType = TimeStats::JankType::Display; } } + if (std::abs(sfActuals.startTime - sfPredictions.startTime) > kSFStartThreshold) { displayFrame->jankMetadata |= sfActuals.startTime > sfPredictions.startTime ? LateStart : EarlyStart; } + totalJankReasons |= displayFrame->jankType; + for (auto& surfaceFrame : displayFrame->surfaceFrames) { if (surfaceFrame->getPresentState() == SurfaceFrame::PresentState::Presented) { // Only presented SurfaceFrames need to be updated @@ -401,13 +420,13 @@ void FrameTimeline::flushPendingPresentFences() { const auto& predictionState = surfaceFrame->getPredictionState(); if (predictionState == PredictionState::Expired) { // Jank analysis cannot be done on apps that don't use predictions - surfaceFrame->setJankInfo(JankType::PredictionExpired, 0); + surfaceFrame->setJankInfo(TimeStats::JankType::PredictionExpired, 0); continue; } else if (predictionState == PredictionState::Valid) { const auto& actuals = surfaceFrame->getActuals(); const auto& predictions = surfaceFrame->getPredictions(); int32_t jankMetadata = 0; - JankType jankType = JankType::None; + TimeStats::JankType jankType = TimeStats::JankType::None; if (std::abs(actuals.endTime - predictions.endTime) > kDeadlineThreshold) { jankMetadata |= actuals.endTime > predictions.endTime ? LateFinish : EarlyFinish; @@ -419,19 +438,26 @@ void FrameTimeline::flushPendingPresentFences() { : EarlyPresent; } if (jankMetadata & EarlyPresent) { - jankType = JankType::SurfaceFlingerEarlyLatch; + jankType = TimeStats::JankType::SurfaceFlingerEarlyLatch; } else if (jankMetadata & LatePresent) { if (jankMetadata & EarlyFinish) { // TODO(b/169890654): Classify this properly - jankType = JankType::Display; + jankType = TimeStats::JankType::Display; } else { - jankType = JankType::AppDeadlineMissed; + jankType = TimeStats::JankType::AppDeadlineMissed; } } + + totalJankReasons |= jankType; + mTimeStats->incrementJankyFrames(surfaceFrame->getOwnerUid(), + surfaceFrame->getName(), + jankType | displayFrame->jankType); surfaceFrame->setJankInfo(jankType, jankMetadata); } } } + + mTimeStats->incrementJankyFrames(totalJankReasons); } mPendingPresentFences.erase(mPendingPresentFences.begin() + static_cast<int>(i)); @@ -467,7 +493,7 @@ nsecs_t FrameTimeline::findBaseTime(const std::shared_ptr<DisplayFrame>& display void FrameTimeline::dumpDisplayFrame(std::string& result, const std::shared_ptr<DisplayFrame>& displayFrame, nsecs_t baseTime) { - if (displayFrame->jankType != JankType::None) { + if (displayFrame->jankType != TimeStats::JankType::None) { // Easily identify a janky Display Frame in the dump StringAppendF(&result, " [*] "); } @@ -501,11 +527,11 @@ void FrameTimeline::dumpJank(std::string& result) { nsecs_t baseTime = (mDisplayFrames.empty()) ? 0 : findBaseTime(mDisplayFrames[0]); for (size_t i = 0; i < mDisplayFrames.size(); i++) { const auto& displayFrame = mDisplayFrames[i]; - if (displayFrame->jankType == JankType::None) { + if (displayFrame->jankType == TimeStats::JankType::None) { // Check if any Surface Frame has been janky bool isJanky = false; for (const auto& surfaceFrame : displayFrame->surfaceFrames) { - if (surfaceFrame->getJankType() != JankType::None) { + if (surfaceFrame->getJankType() != TimeStats::JankType::None) { isJanky = true; break; } diff --git a/services/surfaceflinger/FrameTimeline/FrameTimeline.h b/services/surfaceflinger/FrameTimeline/FrameTimeline.h index bd637df8bc..33821e51c3 100644 --- a/services/surfaceflinger/FrameTimeline/FrameTimeline.h +++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.h @@ -16,9 +16,7 @@ #pragma once -#include <deque> -#include <mutex> - +#include <../TimeStats/TimeStats.h> #include <gui/ISurfaceComposer.h> #include <ui/FenceTime.h> #include <utils/RefBase.h> @@ -26,26 +24,10 @@ #include <utils/Timers.h> #include <utils/Vector.h> -namespace android::frametimeline { +#include <deque> +#include <mutex> -/* - * The type of jank that is associated with a Display/Surface frame - */ -enum class JankType { - // No Jank - None, - // Jank not related to SurfaceFlinger or the App - Display, - // SF took too long on the CPU - SurfaceFlingerDeadlineMissed, - // Either App or GPU took too long on the frame - AppDeadlineMissed, - // Predictions live for 120ms, if prediction is expired for a frame, there is definitely a jank - // associated with the App if this is for a SurfaceFrame, and SF for a DisplayFrame. - PredictionExpired, - // Latching a buffer early might cause an early present of the frame - SurfaceFlingerEarlyLatch, -}; +namespace android::frametimeline { enum JankMetadata { // Frame was presented earlier than expected @@ -147,8 +129,10 @@ public: // Create a new surface frame, set the predictions based on a token and return it to the caller. // Sets the PredictionState of SurfaceFrame. + // Debug name is the human-readable debugging string for dumpsys. virtual std::unique_ptr<SurfaceFrame> createSurfaceFrameForToken( - const std::string& layerName, std::optional<int64_t> token) = 0; + uid_t uid, std::string layerName, std::string debugName, + std::optional<int64_t> token) = 0; // Adds a new SurfaceFrame to the current DisplayFrame. Frames from multiple layers can be // composited into one display frame. @@ -206,8 +190,8 @@ private: class SurfaceFrame : public android::frametimeline::SurfaceFrame { public: - SurfaceFrame(const std::string& layerName, PredictionState predictionState, - TimelineItem&& predictions); + SurfaceFrame(uid_t uid, std::string layerName, std::string debugName, + PredictionState predictionState, TimelineItem&& predictions); ~SurfaceFrame() = default; TimelineItem getPredictions() const override { return mPredictions; }; @@ -221,32 +205,37 @@ public: void setAcquireFenceTime(nsecs_t acquireFenceTime) override; void setPresentState(PresentState state) override; void setActualPresentTime(nsecs_t presentTime); - void setJankInfo(JankType jankType, int32_t jankMetadata); - JankType getJankType() const; + void setJankInfo(TimeStats::JankType jankType, int32_t jankMetadata); + TimeStats::JankType getJankType() const; nsecs_t getBaseTime() const; + uid_t getOwnerUid() const; + const std::string& getName() const; // All the timestamps are dumped relative to the baseTime void dump(std::string& result, const std::string& indent, nsecs_t baseTime); private: + const uid_t mOwnerUid; const std::string mLayerName; + const std::string mDebugName; PresentState mPresentState GUARDED_BY(mMutex); const PredictionState mPredictionState; const TimelineItem mPredictions; TimelineItem mActuals GUARDED_BY(mMutex); nsecs_t mActualQueueTime GUARDED_BY(mMutex); mutable std::mutex mMutex; - JankType mJankType GUARDED_BY(mMutex); // Enum for the type of jank + TimeStats::JankType mJankType GUARDED_BY(mMutex); // Enum for the type of jank int32_t mJankMetadata GUARDED_BY(mMutex); // Additional details about the jank }; class FrameTimeline : public android::frametimeline::FrameTimeline { public: - FrameTimeline(); + FrameTimeline(std::shared_ptr<TimeStats> timeStats); ~FrameTimeline() = default; frametimeline::TokenManager* getTokenManager() override { return &mTokenManager; } std::unique_ptr<frametimeline::SurfaceFrame> createSurfaceFrameForToken( - const std::string& layerName, std::optional<int64_t> token) override; + uid_t ownerUid, std::string layerName, std::string debugName, + std::optional<int64_t> token) override; void addSurfaceFrame(std::unique_ptr<frametimeline::SurfaceFrame> surfaceFrame, SurfaceFrame::PresentState state) override; void setSfWakeUp(int64_t token, nsecs_t wakeupTime) override; @@ -278,7 +267,7 @@ private: std::vector<std::unique_ptr<SurfaceFrame>> surfaceFrames; PredictionState predictionState; - JankType jankType = JankType::None; // Enum for the type of jank + TimeStats::JankType jankType = TimeStats::JankType::None; // Enum for the type of jank int32_t jankMetadata = 0x0; // Additional details about the jank }; @@ -300,6 +289,7 @@ private: TokenManager mTokenManager; std::mutex mMutex; uint32_t mMaxDisplayFrames; + std::shared_ptr<TimeStats> mTimeStats; static constexpr uint32_t kDefaultMaxDisplayFrames = 64; // The initial container size for the vector<SurfaceFrames> inside display frame. Although this // number doesn't represent any bounds on the number of surface frames that can go in a display diff --git a/services/surfaceflinger/Layer.cpp b/services/surfaceflinger/Layer.cpp index d9faec41ea..bef52b73e5 100644 --- a/services/surfaceflinger/Layer.cpp +++ b/services/surfaceflinger/Layer.cpp @@ -897,7 +897,8 @@ bool Layer::applyPendingStates(State* stateToCommit) { : std::make_optional(stateToCommit->frameTimelineVsyncId); auto surfaceFrame = - mFlinger->mFrameTimeline->createSurfaceFrameForToken(mTransactionName, vsyncId); + mFlinger->mFrameTimeline->createSurfaceFrameForToken(getOwnerUid(), mName, + mTransactionName, vsyncId); surfaceFrame->setActualQueueTime(stateToCommit->postTime); // For transactions we set the acquire fence time to the post time as we // don't have a buffer. For BufferStateLayer it is overridden in @@ -1730,7 +1731,7 @@ void Layer::addAndGetFrameTimestamps(const NewFrameEventsEntry* newTimestamps, FrameEventHistoryDelta* outDelta) { if (newTimestamps) { mFlinger->mTimeStats->setPostTime(getSequence(), newTimestamps->frameNumber, - getName().c_str(), newTimestamps->postedTime); + getName().c_str(), mOwnerUid, newTimestamps->postedTime); mFlinger->mTimeStats->setAcquireFence(getSequence(), newTimestamps->frameNumber, newTimestamps->acquireFence); } diff --git a/services/surfaceflinger/Layer.h b/services/surfaceflinger/Layer.h index 02593d57ef..2321247871 100644 --- a/services/surfaceflinger/Layer.h +++ b/services/surfaceflinger/Layer.h @@ -1040,6 +1040,10 @@ protected: // Can only be accessed with the SF state lock held. std::unique_ptr<frametimeline::SurfaceFrame> mSurfaceFrame; + // The owner of the layer. If created from a non system process, it will be the calling uid. + // If created from a system process, the value can be passed in. + uid_t mOwnerUid; + private: virtual void setTransformHint(ui::Transform::RotationFlags) {} @@ -1097,10 +1101,6 @@ private: pid_t mCallingPid; uid_t mCallingUid; - // The owner of the layer. If created from a non system process, it will be the calling uid. - // If created from a system process, the value can be passed in. - uid_t mOwnerUid; - // The current layer is a clone of mClonedFrom. This means that this layer will update it's // properties based on mClonedFrom. When mClonedFrom latches a new buffer for BufferLayers, // this layer will update it's buffer. When mClonedFrom updates it's drawing state, children, diff --git a/services/surfaceflinger/SurfaceFlinger.cpp b/services/surfaceflinger/SurfaceFlinger.cpp index 2ff26a94ad..31c380e392 100644 --- a/services/surfaceflinger/SurfaceFlinger.cpp +++ b/services/surfaceflinger/SurfaceFlinger.cpp @@ -331,7 +331,7 @@ SurfaceFlinger::SurfaceFlinger(Factory& factory, SkipInitializationTag) mInterceptor(mFactory.createSurfaceInterceptor()), mTimeStats(std::make_shared<impl::TimeStats>()), mFrameTracer(std::make_unique<FrameTracer>()), - mFrameTimeline(std::make_unique<frametimeline::impl::FrameTimeline>()), + mFrameTimeline(std::make_unique<frametimeline::impl::FrameTimeline>(mTimeStats)), mEventQueue(mFactory.createMessageQueue()), mCompositionEngine(mFactory.createCompositionEngine()), mInternalDisplayDensity(getDensityFromProperty("ro.sf.lcd_density", true)), diff --git a/services/surfaceflinger/TimeStats/TimeStats.cpp b/services/surfaceflinger/TimeStats/TimeStats.cpp index 37194c6355..fe9e7378db 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.cpp +++ b/services/surfaceflinger/TimeStats/TimeStats.cpp @@ -14,9 +14,6 @@ * limitations under the License. */ -// TODO(b/129481165): remove the #pragma below and fix conversion issues -#pragma clang diagnostic push -#pragma clang diagnostic ignored "-Wconversion" #undef LOG_TAG #define LOG_TAG "TimeStats" #define ATRACE_TAG ATRACE_TAG_GRAPHICS @@ -33,6 +30,8 @@ #include <algorithm> #include <chrono> +#include "timestatsproto/TimeStatsHelper.h" + namespace android { namespace impl { @@ -115,6 +114,13 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateGlobalAtom(AStatsEventLi 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); mStatsDelegate->statsEventBuild(event); clearGlobalLocked(); @@ -160,6 +166,13 @@ AStatsManager_PullAtomCallbackReturn TimeStats::populateLayerAtom(AStatsEventLis mStatsDelegate->statsEventWriteInt64(event, layer->lateAcquireFrames); mStatsDelegate->statsEventWriteInt64(event, layer->badDesiredPresentFrames); + mStatsDelegate->statsEventWriteInt32(event, layer->uid); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalFrames); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalJankyFrames); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFLongCpu); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFLongGpu); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalSFUnattributed); + mStatsDelegate->statsEventWriteInt32(event, layer->jankPayload.totalAppUnattributed); mStatsDelegate->statsEventBuild(event); } @@ -397,11 +410,13 @@ void TimeStats::flushAvailableRecordsToStatsLocked(int32_t layerId) { timeRecords[0].frameTime.frameNumber, timeRecords[0].frameTime.presentTime); if (prevTimeRecord.ready) { + uid_t uid = layerRecord.uid; const std::string& layerName = layerRecord.layerName; - if (!mTimeStats.stats.count(layerName)) { - mTimeStats.stats[layerName].layerName = layerName; + if (!mTimeStats.stats.count({uid, layerName})) { + mTimeStats.stats[{uid, layerName}].uid = uid; + mTimeStats.stats[{uid, layerName}].layerName = layerName; } - TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[layerName]; + TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[{uid, layerName}]; timeStatsLayer.totalFrames++; timeStatsLayer.droppedFrames += layerRecord.droppedFrames; timeStatsLayer.lateAcquireFrames += layerRecord.lateAcquireFrames; @@ -462,8 +477,13 @@ static bool layerNameIsValid(const std::string& layerName) { layerName.compare(0, kMinLenLayerName, kPopupWindowPrefix) != 0; } +bool TimeStats::canAddNewAggregatedStats(uid_t uid, const std::string& layerName) { + return mTimeStats.stats.count({uid, layerName}) > 0 || + mTimeStats.stats.size() < MAX_NUM_LAYER_STATS; +} + void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName, - nsecs_t postTime) { + uid_t uid, nsecs_t postTime) { if (!mEnabled.load()) return; ATRACE_CALL(); @@ -471,11 +491,12 @@ void TimeStats::setPostTime(int32_t layerId, uint64_t frameNumber, const std::st postTime); std::lock_guard<std::mutex> lock(mMutex); - if (!mTimeStats.stats.count(layerName) && mTimeStats.stats.size() >= MAX_NUM_LAYER_STATS) { + if (!canAddNewAggregatedStats(uid, layerName)) { return; } if (!mTimeStatsTracker.count(layerId) && mTimeStatsTracker.size() < MAX_NUM_LAYER_RECORDS && layerNameIsValid(layerName)) { + mTimeStatsTracker[layerId].uid = uid; mTimeStatsTracker[layerId].layerName = layerName; } if (!mTimeStatsTracker.count(layerId)) return; @@ -655,6 +676,66 @@ void TimeStats::setPresentFence(int32_t layerId, uint64_t frameNumber, flushAvailableRecordsToStatsLocked(layerId); } +template <class T> +static void updateJankPayload(T& t, int32_t reasons) { + t.jankPayload.totalFrames++; + + static const constexpr int32_t kValidJankyReason = + TimeStats::JankType::SurfaceFlingerDeadlineMissed | + TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed | + TimeStats::JankType::AppDeadlineMissed | TimeStats::JankType::Display; + if (reasons & kValidJankyReason) { + t.jankPayload.totalJankyFrames++; + if ((reasons & TimeStats::JankType::SurfaceFlingerDeadlineMissed) != 0) { + t.jankPayload.totalSFLongCpu++; + } + if ((reasons & TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed) != 0) { + t.jankPayload.totalSFLongGpu++; + } + if ((reasons & TimeStats::JankType::Display) != 0) { + t.jankPayload.totalSFUnattributed++; + } + if ((reasons & TimeStats::JankType::AppDeadlineMissed) != 0) { + t.jankPayload.totalAppUnattributed++; + } + } +} + +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) { + if (!mEnabled.load()) return; + + ATRACE_CALL(); + std::lock_guard<std::mutex> lock(mMutex); + + // Only update layer stats if we're allowed to do so. + // As an implementation detail, we do this because this method is expected to be + // called from FrameTimeline, which is allowed to do jank analysis well after a frame is + // presented. This means that we can't rely on TimeStats to flush layer records over to the + // aggregated stats. + if (!canAddNewAggregatedStats(uid, layerName)) { + return; + } + + // Defensively initialize the stats in case FrameTimeline flushes its signaled present fences + // before TimeStats does. + if (!mTimeStats.stats.count({uid, layerName})) { + mTimeStats.stats[{uid, layerName}].uid = uid; + mTimeStats.stats[{uid, layerName}].layerName = layerName; + } + + TimeStatsHelper::TimeStatsLayer& timeStatsLayer = mTimeStats.stats[{uid, layerName}]; + updateJankPayload<TimeStatsHelper::TimeStatsLayer>(timeStatsLayer, reasons); +} + void TimeStats::onDestroy(int32_t layerId) { ATRACE_CALL(); ALOGV("[%d]-onDestroy", layerId); @@ -860,6 +941,7 @@ void TimeStats::clearGlobalLocked() { mTimeStats.presentToPresent.hist.clear(); mTimeStats.frameDuration.hist.clear(); mTimeStats.renderEngineTiming.hist.clear(); + mTimeStats.jankPayload = TimeStatsHelper::JankPayload(); mTimeStats.refreshRateStats.clear(); mPowerTime.prevTime = systemTime(); mGlobalRecord.prevPresentTime = 0; @@ -905,6 +987,3 @@ void TimeStats::dump(bool asProto, std::optional<uint32_t> maxLayers, std::strin } // namespace impl } // namespace android - -// TODO(b/129481165): remove the #pragma below and fix conversion issues -#pragma clang diagnostic pop // ignored "-Wconversion" diff --git a/services/surfaceflinger/TimeStats/TimeStats.h b/services/surfaceflinger/TimeStats/TimeStats.h index 8de5d0c3e8..4fa0a02770 100644 --- a/services/surfaceflinger/TimeStats/TimeStats.h +++ b/services/surfaceflinger/TimeStats/TimeStats.h @@ -17,6 +17,7 @@ #pragma once // TODO(b/129481165): remove the #pragma below and fix conversion issues +#include <cstdint> #pragma clang diagnostic push #pragma clang diagnostic ignored "-Wconversion" @@ -85,7 +86,7 @@ public: const std::shared_ptr<FenceTime>& readyFence) = 0; virtual void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName, - nsecs_t postTime) = 0; + uid_t uid, nsecs_t postTime) = 0; virtual void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) = 0; // Reasons why latching a particular buffer may be skipped enum class LatchSkipReason { @@ -108,6 +109,40 @@ public: virtual void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) = 0; virtual void setPresentFence(int32_t layerId, uint64_t frameNumber, const std::shared_ptr<FenceTime>& presentFence) = 0; + + // Subset of jank metadata tracked by FrameTimeline for the purpose of funneling to telemetry. + enum JankType { + // No Jank + None = 0x0, + // Jank not related to SurfaceFlinger or the App + Display = 0x1, + // SF took too long on the CPU + SurfaceFlingerDeadlineMissed = 0x2, + // SF took too long on the GPU + SurfaceFlingerGpuDeadlineMissed = 0x4, + // Either App or GPU took too long on the frame + AppDeadlineMissed = 0x8, + // Predictions live for 120ms, if prediction is expired for a frame, there is definitely a + // jank + // associated with the App if this is for a SurfaceFrame, and SF for a DisplayFrame. + PredictionExpired = 0x10, + // Latching a buffer early might cause an early present of the frame + SurfaceFlingerEarlyLatch = 0x20, + }; + + // 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 + // accounting of janky frames. + virtual void incrementJankyFrames(uid_t uid, const std::string& layerName, int32_t reasons) = 0; // Clean up the layer record virtual void onDestroy(int32_t layerId) = 0; // If SF skips or rejects a buffer, remove the corresponding TimeRecord. @@ -142,6 +177,7 @@ class TimeStats : public android::TimeStats { }; struct LayerRecord { + uid_t uid; std::string layerName; // This is the index in timeRecords, at which the timestamps for that // specific frame are still not fully received. This is not waiting for @@ -241,7 +277,7 @@ public: void recordRenderEngineDuration(nsecs_t startTime, const std::shared_ptr<FenceTime>& readyFence) override; - void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName, + void setPostTime(int32_t layerId, uint64_t frameNumber, const std::string& layerName, uid_t uid, nsecs_t postTime) override; void setLatchTime(int32_t layerId, uint64_t frameNumber, nsecs_t latchTime) override; void incrementLatchSkipped(int32_t layerId, LatchSkipReason reason) override; @@ -253,6 +289,8 @@ public: void setPresentTime(int32_t layerId, uint64_t frameNumber, nsecs_t presentTime) 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; // Clean up the layer record void onDestroy(int32_t layerId) override; // If SF skips or rejects a buffer, remove the corresponding TimeRecord. @@ -276,6 +314,7 @@ private: void flushAvailableRecordsToStatsLocked(int32_t layerId); void flushPowerTimeLocked(); void flushAvailableGlobalRecordsToStatsLocked(); + bool canAddNewAggregatedStats(uid_t uid, const std::string& layerName); void enable(); void disable(); diff --git a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp index d77387a895..0fb748f1a6 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp +++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp @@ -77,14 +77,28 @@ std::string TimeStatsHelper::Histogram::toString() const { return result; } +std::string TimeStatsHelper::JankPayload::toString() const { + std::string result; + StringAppendF(&result, "totalTimelineFrames = %d\n", totalFrames); + StringAppendF(&result, "jankyFrames = %d\n", totalJankyFrames); + StringAppendF(&result, "sfLongCpuJankyFrames = %d\n", totalSFLongCpu); + StringAppendF(&result, "sfLongGpuJankyFrames = %d\n", totalSFLongGpu); + StringAppendF(&result, "sfUnattributedJankyFrame = %d\n", totalSFUnattributed); + StringAppendF(&result, "appUnattributedJankyFrame = %d\n", totalAppUnattributed); + return result; +} + std::string TimeStatsHelper::TimeStatsLayer::toString() const { std::string result = "\n"; + StringAppendF(&result, "uid = %d\n", uid); StringAppendF(&result, "layerName = %s\n", layerName.c_str()); StringAppendF(&result, "packageName = %s\n", packageName.c_str()); StringAppendF(&result, "totalFrames = %d\n", totalFrames); StringAppendF(&result, "droppedFrames = %d\n", droppedFrames); StringAppendF(&result, "lateAcquireFrames = %d\n", lateAcquireFrames); StringAppendF(&result, "badDesiredPresentFrames = %d\n", badDesiredPresentFrames); + result.append("Jank payload for this layer:\n"); + result.append(jankPayload.toString()); const auto iter = deltas.find("present2present"); if (iter != deltas.end()) { const float averageTime = iter->second.averageTime(); @@ -110,6 +124,8 @@ std::string TimeStatsHelper::TimeStatsGlobal::toString(std::optional<uint32_t> m 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()); StringAppendF(&result, "displayConfigStats is as below:\n"); for (const auto& [fps, duration] : refreshRateStats) { StringAppendF(&result, "%dfps = %ldms\n", fps, ns2ms(duration)); diff --git a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h index 0c75f96e46..033eb5dcd9 100644 --- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h +++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h @@ -40,14 +40,28 @@ public: std::string toString() const; }; + struct JankPayload { + // note that transactions are counted for these frames. + int32_t totalFrames = 0; + int32_t totalJankyFrames = 0; + int32_t totalSFLongCpu = 0; + int32_t totalSFLongGpu = 0; + int32_t totalSFUnattributed = 0; + int32_t totalAppUnattributed = 0; + + std::string toString() const; + }; + class TimeStatsLayer { public: + uid_t uid; std::string layerName; std::string packageName; int32_t totalFrames = 0; int32_t droppedFrames = 0; int32_t lateAcquireFrames = 0; int32_t badDesiredPresentFrames = 0; + JankPayload jankPayload; std::unordered_map<std::string, Histogram> deltas; std::string toString() const; @@ -69,8 +83,17 @@ public: Histogram presentToPresent; Histogram frameDuration; Histogram renderEngineTiming; - std::unordered_map<std::string, TimeStatsLayer> stats; + + 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); + } + }; + std::unordered_map<std::pair<uid_t, std::string>, TimeStatsLayer, StatsHasher> stats; std::unordered_map<uint32_t, nsecs_t> refreshRateStats; + JankPayload jankPayload; 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 69efd7f477..5e9d64af0f 100644 --- a/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp +++ b/services/surfaceflinger/tests/unittests/FrameTimelineTest.cpp @@ -14,6 +14,8 @@ * limitations under the License. */ +#include "gmock/gmock-spec-builders.h" +#include "mock/MockTimeStats.h" #undef LOG_TAG #define LOG_TAG "LibSurfaceFlingerUnittests" @@ -23,6 +25,11 @@ #include <cinttypes> using namespace std::chrono_literals; +using testing::Contains; + +MATCHER_P(HasBit, bit, "") { + return (arg & bit) != 0; +} namespace android::frametimeline { @@ -41,7 +48,8 @@ public: } void SetUp() override { - mFrameTimeline = std::make_unique<impl::FrameTimeline>(); + mTimeStats = std::make_shared<mock::TimeStats>(); + mFrameTimeline = std::make_unique<impl::FrameTimeline>(mTimeStats); mTokenManager = &mFrameTimeline->mTokenManager; maxDisplayFrames = &mFrameTimeline->mMaxDisplayFrames; maxTokenRetentionTime = mTokenManager->kMaxRetentionTime; @@ -76,6 +84,7 @@ public: return static_cast<uint32_t>(mFrameTimeline->mDisplayFrames.size()); } + std::shared_ptr<mock::TimeStats> mTimeStats; std::unique_ptr<impl::FrameTimeline> mFrameTimeline; impl::TokenManager* mTokenManager; FenceToFenceTimeMap fenceFactory; @@ -83,6 +92,10 @@ public: nsecs_t maxTokenRetentionTime; }; +static const std::string sLayerNameOne = "layer1"; +static const std::string sLayerNameTwo = "layer2"; +static constexpr const uid_t sUidOne = 0; + TEST_F(FrameTimelineTest, tokenManagerRemovesStalePredictions) { int64_t token1 = mTokenManager->generateTokenForPredictions({0, 0, 0}); EXPECT_EQ(getPredictions().size(), 1); @@ -99,21 +112,24 @@ TEST_F(FrameTimelineTest, tokenManagerRemovesStalePredictions) { } TEST_F(FrameTimelineTest, createSurfaceFrameForToken_noToken) { - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, std::nullopt); EXPECT_EQ(surfaceFrame->getPredictionState(), PredictionState::None); } TEST_F(FrameTimelineTest, createSurfaceFrameForToken_expiredToken) { int64_t token1 = mTokenManager->generateTokenForPredictions({0, 0, 0}); flushTokens(systemTime() + maxTokenRetentionTime); - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", token1); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, token1); EXPECT_EQ(surfaceFrame->getPredictionState(), PredictionState::Expired); } TEST_F(FrameTimelineTest, createSurfaceFrameForToken_validToken) { int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30}); - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", token1); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, token1); EXPECT_EQ(surfaceFrame->getPredictionState(), PredictionState::Valid); EXPECT_EQ(compareTimelineItems(surfaceFrame->getPredictions(), TimelineItem(10, 20, 30)), true); @@ -125,7 +141,8 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_droppedFramesNotUpdated) { int64_t token1 = mTokenManager->generateTokenForPredictions({10, 20, 30}); int64_t token2 = mTokenManager->generateTokenForPredictions({40, 50, 60}); - auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken("layer1", token1); + auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, token1); // Set up the display frame mFrameTimeline->setSfWakeUp(token1, 20); @@ -148,8 +165,12 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { int64_t surfaceFrameToken2 = mTokenManager->generateTokenForPredictions({40, 50, 60}); int64_t sfToken1 = mTokenManager->generateTokenForPredictions({22, 26, 30}); int64_t sfToken2 = mTokenManager->generateTokenForPredictions({52, 56, 60}); - auto surfaceFrame1 = mFrameTimeline->createSurfaceFrameForToken("layer1", surfaceFrameToken1); - auto surfaceFrame2 = mFrameTimeline->createSurfaceFrameForToken("layer2", surfaceFrameToken1); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken1); + auto surfaceFrame2 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameTwo, sLayerNameTwo, + surfaceFrameToken1); mFrameTimeline->setSfWakeUp(sfToken1, 22); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), SurfaceFrame::PresentState::Presented); @@ -168,7 +189,9 @@ TEST_F(FrameTimelineTest, presentFenceSignaled_presentedFramesUpdated) { // Trigger a flush by finalizing the next DisplayFrame auto presentFence2 = fenceFactory.createFenceTimeForTest(Fence::NO_FENCE); - auto surfaceFrame3 = mFrameTimeline->createSurfaceFrameForToken("layer1", surfaceFrameToken2); + auto surfaceFrame3 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken2); mFrameTimeline->setSfWakeUp(sfToken2, 52); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame3), SurfaceFrame::PresentState::Dropped); mFrameTimeline->setSfPresent(56, presentFence2); @@ -189,7 +212,9 @@ TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { {10 + frameTimeFactor, 20 + frameTimeFactor, 30 + frameTimeFactor}); int64_t sfToken = mTokenManager->generateTokenForPredictions( {22 + frameTimeFactor, 26 + frameTimeFactor, 30 + frameTimeFactor}); - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", surfaceFrameToken); + auto surfaceFrame = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken); mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), SurfaceFrame::PresentState::Presented); @@ -209,7 +234,9 @@ TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { {10 + frameTimeFactor, 20 + frameTimeFactor, 30 + frameTimeFactor}); int64_t sfToken = mTokenManager->generateTokenForPredictions( {22 + frameTimeFactor, 26 + frameTimeFactor, 30 + frameTimeFactor}); - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", surfaceFrameToken); + auto surfaceFrame = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken); mFrameTimeline->setSfWakeUp(sfToken, 22 + frameTimeFactor); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), SurfaceFrame::PresentState::Presented); mFrameTimeline->setSfPresent(27 + frameTimeFactor, presentFence); @@ -224,7 +251,8 @@ TEST_F(FrameTimelineTest, displayFramesSlidingWindowMovesAfterLimit) { TEST_F(FrameTimelineTest, surfaceFrameEndTimeAcquireFenceAfterQueue) { auto surfaceFrame = - mFrameTimeline->createSurfaceFrameForToken("acquireFenceAfterQueue", std::nullopt); + mFrameTimeline->createSurfaceFrameForToken(0, "acquireFenceAfterQueue", + "acquireFenceAfterQueue", std::nullopt); surfaceFrame->setActualQueueTime(123); surfaceFrame->setAcquireFenceTime(456); EXPECT_EQ(surfaceFrame->getActuals().endTime, 456); @@ -232,7 +260,8 @@ TEST_F(FrameTimelineTest, surfaceFrameEndTimeAcquireFenceAfterQueue) { TEST_F(FrameTimelineTest, surfaceFrameEndTimeAcquireFenceBeforeQueue) { auto surfaceFrame = - mFrameTimeline->createSurfaceFrameForToken("acquireFenceAfterQueue", std::nullopt); + mFrameTimeline->createSurfaceFrameForToken(0, "acquireFenceAfterQueue", + "acquireFenceAfterQueue", std::nullopt); surfaceFrame->setActualQueueTime(456); surfaceFrame->setAcquireFenceTime(123); EXPECT_EQ(surfaceFrame->getActuals().endTime, 456); @@ -244,7 +273,8 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { // Size shouldn't exceed maxDisplayFrames - 64 for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, std::nullopt); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); mFrameTimeline->setSfWakeUp(sfToken, 22); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), @@ -258,7 +288,8 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { EXPECT_EQ(*maxDisplayFrames, 256); for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, std::nullopt); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); mFrameTimeline->setSfWakeUp(sfToken, 22); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), @@ -272,7 +303,8 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { EXPECT_EQ(*maxDisplayFrames, 128); for (size_t i = 0; i < *maxDisplayFrames + 10; i++) { - auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken("layer1", std::nullopt); + auto surfaceFrame = mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, + sLayerNameOne, std::nullopt); int64_t sfToken = mTokenManager->generateTokenForPredictions({22, 26, 30}); mFrameTimeline->setSfWakeUp(sfToken, 22); mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame), @@ -281,4 +313,90 @@ TEST_F(FrameTimelineTest, setMaxDisplayFramesSetsSizeProperly) { } EXPECT_EQ(getNumberOfDisplayFrames(), *maxDisplayFrames); } + +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsLongSfCpu) { + EXPECT_CALL(*mTimeStats, + incrementJankyFrames(sUidOne, sLayerNameOne, + HasBit(TimeStats::JankType::SurfaceFlingerDeadlineMissed))); + EXPECT_CALL(*mTimeStats, + incrementJankyFrames(HasBit(TimeStats::JankType::SurfaceFlingerDeadlineMissed))); + 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>(52ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken1); + mFrameTimeline->setSfWakeUp(sfToken1, + std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count()); + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), + SurfaceFrame::PresentState::Presented); + presentFence1->signalForTest( + std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); + + mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(59ms).count(), + presentFence1); +} + +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsDisplayMiss) { + EXPECT_CALL(*mTimeStats, + incrementJankyFrames(sUidOne, sLayerNameOne, HasBit(TimeStats::JankType::Display))); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(HasBit(TimeStats::JankType::Display))); + 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>(52ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken1); + mFrameTimeline->setSfWakeUp(sfToken1, + std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count()); + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), + SurfaceFrame::PresentState::Presented); + presentFence1->signalForTest( + std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(59ms).count(), + presentFence1); +} + +TEST_F(FrameTimelineTest, presentFenceSignaled_reportsAppMiss) { + EXPECT_CALL(*mTimeStats, + incrementJankyFrames(sUidOne, sLayerNameOne, + HasBit(TimeStats::JankType::AppDeadlineMissed))); + EXPECT_CALL(*mTimeStats, incrementJankyFrames(HasBit(TimeStats::JankType::AppDeadlineMissed))); + 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>(52ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), + std::chrono::duration_cast<std::chrono::nanoseconds>(60ms).count()}); + auto surfaceFrame1 = + mFrameTimeline->createSurfaceFrameForToken(sUidOne, sLayerNameOne, sLayerNameOne, + surfaceFrameToken1); + surfaceFrame1->setAcquireFenceTime( + std::chrono::duration_cast<std::chrono::nanoseconds>(45ms).count()); + mFrameTimeline->setSfWakeUp(sfToken1, + std::chrono::duration_cast<std::chrono::nanoseconds>(52ms).count()); + + mFrameTimeline->addSurfaceFrame(std::move(surfaceFrame1), + SurfaceFrame::PresentState::Presented); + presentFence1->signalForTest( + std::chrono::duration_cast<std::chrono::nanoseconds>(90ms).count()); + mFrameTimeline->setSfPresent(std::chrono::duration_cast<std::chrono::nanoseconds>(56ms).count(), + presentFence1); +} + } // namespace android::frametimeline diff --git a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp index 0a246505ca..a90f4247a9 100644 --- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp +++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp @@ -58,6 +58,7 @@ using PowerMode = hardware::graphics::composer::V2_4::IComposerClient::PowerMode #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" @@ -227,7 +228,8 @@ static std::string genLayerName(int32_t layerId) { void TimeStatsTest::setTimeStamp(TimeStamp type, int32_t id, uint64_t frameNumber, nsecs_t ts) { switch (type) { case TimeStamp::POST: - ASSERT_NO_FATAL_FAILURE(mTimeStats->setPostTime(id, frameNumber, genLayerName(id), ts)); + ASSERT_NO_FATAL_FAILURE( + mTimeStats->setPostTime(id, frameNumber, genLayerName(id), UID_0, ts)); break; case TimeStamp::ACQUIRE: ASSERT_NO_FATAL_FAILURE(mTimeStats->setAcquireTime(id, frameNumber, ts)); @@ -349,6 +351,61 @@ TEST_F(TimeStatsTest, canIncreaseBadDesiredPresent) { EXPECT_THAT(result, HasSubstr(expectedResult)); } +TEST_F(TimeStatsTest, canIncreaseJankyFrames) { + // 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(TimeStats::JankType::SurfaceFlingerDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::Display); + mTimeStats->incrementJankyFrames(TimeStats::JankType::AppDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::None); + + 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); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfLongCpuJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfLongGpuJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfUnattributedJankyFrame = " + std::to_string(1); + 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), + TimeStats::JankType::SurfaceFlingerDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::Display); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::AppDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::None); + + 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); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfLongCpuJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfLongGpuJankyFrames = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "sfUnattributedJankyFrame = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); + expectedResult = "appUnattributedJankyFrame = " + std::to_string(1); + EXPECT_THAT(result, HasSubstr(expectedResult)); +} + TEST_F(TimeStatsTest, canIncreaseClientCompositionReusedFrames) { // this stat is not in the proto so verify by checking the string dump constexpr size_t CLIENT_COMPOSITION_REUSED_FRAMES = 2; @@ -789,6 +846,16 @@ TEST_F(TimeStatsTest, canClearDumpOnlyTimeStats) { .count()); mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>( std::chrono::duration_cast<std::chrono::nanoseconds>(1ms).count())); + + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::SurfaceFlingerDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::Display); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::AppDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::None); + EXPECT_TRUE(inputCommand(InputCommand::CLEAR, FMT_STRING).empty()); const std::string result(inputCommand(InputCommand::DUMP_ALL, FMT_STRING)); @@ -797,6 +864,11 @@ 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) { @@ -904,6 +976,8 @@ TEST_F(TimeStatsTest, globalStatsCallback) { mTimeStats->incrementClientCompositionFrames(); } + insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 1, 1000000); + mTimeStats->recordDisplayEventConnectionCount(DISPLAY_EVENT_CONNECTIONS); mTimeStats->setPowerMode(PowerMode::ON); mTimeStats->recordFrameDuration(1000000, 3000000); @@ -913,6 +987,12 @@ TEST_F(TimeStatsTest, globalStatsCallback) { mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(3000000)); mTimeStats->setPresentFenceGlobal(std::make_shared<FenceTime>(5000000)); + mTimeStats->incrementJankyFrames(TimeStats::JankType::SurfaceFlingerDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::Display); + mTimeStats->incrementJankyFrames(TimeStats::JankType::AppDeadlineMissed); + mTimeStats->incrementJankyFrames(TimeStats::JankType::None); + EXPECT_THAT(mDelegate->mAtomTags, UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO, android::util::SURFACEFLINGER_STATS_LAYER_INFO)); @@ -944,6 +1024,12 @@ TEST_F(TimeStatsTest, globalStatsCallback) { expectedRenderEngineTiming.c_str(), expectedRenderEngineTiming.size()), expectedRenderEngineTiming.size())); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 5)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 4)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent)); } EXPECT_EQ(AStatsManager_PULL_SUCCESS, @@ -975,6 +1061,15 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { } insertTimeRecord(NORMAL_SEQUENCE, LAYER_ID_0, 2, 2000000); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::SurfaceFlingerDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::SurfaceFlingerGpuDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::Display); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), + TimeStats::JankType::AppDeadlineMissed); + mTimeStats->incrementJankyFrames(UID_0, genLayerName(LAYER_ID_0), TimeStats::JankType::None); + EXPECT_THAT(mDelegate->mAtomTags, UnorderedElementsAre(android::util::SURFACEFLINGER_STATS_GLOBAL_INFO, android::util::SURFACEFLINGER_STATS_LAYER_INFO)); @@ -1033,6 +1128,14 @@ TEST_F(TimeStatsTest, layerStatsCallback_pullsAllAndClears) { EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, LATE_ACQUIRE_FRAMES)); EXPECT_CALL(*mDelegate, statsEventWriteInt64(mDelegate->mEvent, BAD_DESIRED_PRESENT_FRAMES)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, UID_0)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 5)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 4)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventWriteInt32(mDelegate->mEvent, 1)); + EXPECT_CALL(*mDelegate, statsEventBuild(mDelegate->mEvent)); } EXPECT_EQ(AStatsManager_PULL_SUCCESS, diff --git a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h index ff37ec8018..99ec353095 100644 --- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h +++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h @@ -41,7 +41,7 @@ public: MOCK_METHOD2(recordFrameDuration, void(nsecs_t, nsecs_t)); MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, nsecs_t)); MOCK_METHOD2(recordRenderEngineDuration, void(nsecs_t, const std::shared_ptr<FenceTime>&)); - MOCK_METHOD4(setPostTime, void(int32_t, uint64_t, const std::string&, nsecs_t)); + MOCK_METHOD5(setPostTime, void(int32_t, uint64_t, const std::string&, uid_t, nsecs_t)); MOCK_METHOD2(incrementLatchSkipped, void(int32_t layerId, LatchSkipReason reason)); MOCK_METHOD1(incrementBadDesiredPresent, void(int32_t layerId)); MOCK_METHOD3(setLatchTime, void(int32_t, uint64_t, nsecs_t)); @@ -50,6 +50,8 @@ public: 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_METHOD1(onDestroy, void(int32_t)); MOCK_METHOD2(removeTimeRecord, void(int32_t, uint64_t)); MOCK_METHOD1(setPowerMode, |