Expose shared timeline counters into telemetry:
* Add UID into both shared timeline and timestats tracking: due to BLAST
APIs, layer name is insufficient for identifying applications
* Plumb through jank counters from shared timeline into timestats and WW
* Fixed bug where SurfaceflingerDeadlineMissed was not being tracked.
One caveat is that transactions are tracked in shared timeline, so as
a consequence timestats will start tracking them as well.
Bug: 171309796
Test: builds, boots
Test: statsd_testdrive
Test: libsurfacefinger_unittest
Test: dumpsys SurfaceFlinger --timestats -dump
Change-Id: I71057c0976ce81bbb605e126cb30b9d6f06c5873
diff --git a/services/surfaceflinger/BufferQueueLayer.cpp b/services/surfaceflinger/BufferQueueLayer.cpp
index 0863a22..51c7ed5 100644
--- a/services/surfaceflinger/BufferQueueLayer.cpp
+++ b/services/surfaceflinger/BufferQueueLayer.cpp
@@ -442,7 +442,8 @@
}
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 @@
}
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 361c1f3..66b4e19 100644
--- a/services/surfaceflinger/BufferStateLayer.cpp
+++ b/services/surfaceflinger/BufferStateLayer.cpp
@@ -276,7 +276,7 @@
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 6ba4c43..e075d3e 100644
--- a/services/surfaceflinger/FrameTimeline/Android.bp
+++ b/services/surfaceflinger/FrameTimeline/Android.bp
@@ -5,10 +5,12 @@
"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 43176a3..996479c 100644
--- a/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
+++ b/services/surfaceflinger/FrameTimeline/FrameTimeline.cpp
@@ -93,19 +93,19 @@
}
}
-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 @@
}
}
-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 @@
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 @@
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 @@
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 @@
}
}
if (signalTime != Fence::SIGNAL_TIME_INVALID) {
+ int32_t totalJankReasons = TimeStats::JankType::None;
auto& displayFrame = pendingPresentFence.second;
displayFrame->surfaceFlingerActuals.presentTime = signalTime;
@@ -377,21 +391,26 @@
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 @@
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 @@
: 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 @@
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 @@
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 bd637df..33821e5 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 @@
// 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 @@
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 @@
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 @@
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 @@
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 d9faec4..bef52b7 100644
--- a/services/surfaceflinger/Layer.cpp
+++ b/services/surfaceflinger/Layer.cpp
@@ -897,7 +897,8 @@
: 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 @@
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 02593d5..2321247 100644
--- a/services/surfaceflinger/Layer.h
+++ b/services/surfaceflinger/Layer.h
@@ -1040,6 +1040,10 @@
// 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 @@
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 2ff26a9..31c380e 100644
--- a/services/surfaceflinger/SurfaceFlinger.cpp
+++ b/services/surfaceflinger/SurfaceFlinger.cpp
@@ -331,7 +331,7 @@
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 37194c6..fe9e737 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
} // 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 8de5d0c..4fa0a02 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 @@
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 @@
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 @@
};
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 @@
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 @@
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 @@
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 d77387a..0fb748f 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
+++ b/services/surfaceflinger/TimeStats/timestatsproto/TimeStatsHelper.cpp
@@ -77,14 +77,28 @@
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 @@
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 0c75f96..033eb5d 100644
--- a/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
+++ b/services/surfaceflinger/TimeStats/timestatsproto/include/timestatsproto/TimeStatsHelper.h
@@ -40,14 +40,28 @@
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 @@
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 69efd7f..5e9d64a 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 @@
}
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 @@
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 @@
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, 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 @@
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 @@
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 @@
// 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 @@
{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 @@
{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, 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, 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 @@
// 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 @@
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 @@
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 @@
}
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 0a24650..a90f424 100644
--- a/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
+++ b/services/surfaceflinger/tests/unittests/TimeStatsTest.cpp
@@ -58,6 +58,7 @@
#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 @@
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 @@
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 @@
.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 @@
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 @@
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 @@
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 @@
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 @@
}
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 @@
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 ff37ec8..99ec353 100644
--- a/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
+++ b/services/surfaceflinger/tests/unittests/mock/MockTimeStats.h
@@ -41,7 +41,7 @@
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 @@
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,