Change hwui jank detection to use deadline & gpu completion (1/2)
- Use GPU finish time as well as actual deadline to determine jank
rate.
- Use dynamic interval to adjust for 60/90hz switching
- Move frame metrics reporting into JankTracker to adjust the
deadline communicated to the app when in stuffing scenario.
- Adjust double-stuffing detection to be a bit more readable.
Test: GraphicsStatsValidationTest.java
Test: adb shell dumpsys gfxinfo
Test: FrameMetricsListenerTest
Test: Log output of FrameMetricsObserver
Bug: 169858044
Change-Id: I3a6b8ed163e2cf9cf2b67667110340ebe35f98a1
diff --git a/libs/hwui/Android.bp b/libs/hwui/Android.bp
index 9270901..f2c48bb 100644
--- a/libs/hwui/Android.bp
+++ b/libs/hwui/Android.bp
@@ -653,6 +653,7 @@
"tests/unit/EglManagerTests.cpp",
"tests/unit/FatVectorTests.cpp",
"tests/unit/GraphicsStatsServiceTests.cpp",
+ "tests/unit/JankTrackerTests.cpp",
"tests/unit/LayerUpdateQueueTests.cpp",
"tests/unit/LinearAllocatorTests.cpp",
"tests/unit/MatrixTests.cpp",
diff --git a/libs/hwui/FrameInfo.cpp b/libs/hwui/FrameInfo.cpp
index 51fbf36..fecf269 100644
--- a/libs/hwui/FrameInfo.cpp
+++ b/libs/hwui/FrameInfo.cpp
@@ -21,16 +21,18 @@
namespace uirenderer {
const std::array FrameInfoNames{
- "Flags", "FrameTimelineVsyncId", "IntendedVsync",
- "Vsync", "InputEventId", "HandleInputStart",
- "AnimationStart", "PerformTraversalsStart", "DrawStart",
- "FrameDeadline", "FrameStartTime", "SyncQueued",
- "SyncStart", "IssueDrawCommandsStart", "SwapBuffers",
- "FrameCompleted", "DequeueBufferDuration", "QueueBufferDuration",
- "GpuCompleted", "SwapBuffersCompleted", "DisplayPresentTime",
+ "Flags", "FrameTimelineVsyncId", "IntendedVsync",
+ "Vsync", "InputEventId", "HandleInputStart",
+ "AnimationStart", "PerformTraversalsStart", "DrawStart",
+ "FrameDeadline", "FrameInterval", "FrameStartTime",
+ "SyncQueued", "SyncStart", "IssueDrawCommandsStart",
+ "SwapBuffers", "FrameCompleted", "DequeueBufferDuration",
+ "QueueBufferDuration", "GpuCompleted", "SwapBuffersCompleted",
+ "DisplayPresentTime",
+
};
-static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 21,
+static_assert(static_cast<int>(FrameInfoIndex::NumIndexes) == 22,
"Must update value in FrameMetrics.java#FRAME_STATS_COUNT (and here)");
void FrameInfo::importUiThreadInfo(int64_t* info) {
diff --git a/libs/hwui/FrameInfo.h b/libs/hwui/FrameInfo.h
index 62ac4ca..2a134fa 100644
--- a/libs/hwui/FrameInfo.h
+++ b/libs/hwui/FrameInfo.h
@@ -28,7 +28,7 @@
namespace android {
namespace uirenderer {
-static constexpr size_t UI_THREAD_FRAME_INFO_SIZE = 11;
+static constexpr size_t UI_THREAD_FRAME_INFO_SIZE = 12;
enum class FrameInfoIndex {
Flags = 0,
@@ -42,6 +42,7 @@
DrawStart,
FrameDeadline,
FrameStartTime,
+ FrameInterval,
// End of UI frame info
SyncQueued,
@@ -77,6 +78,9 @@
class UiFrameInfoBuilder {
public:
static constexpr int64_t INVALID_VSYNC_ID = -1;
+ static constexpr int64_t UNKNOWN_DEADLINE = std::numeric_limits<int64_t>::max();
+ static constexpr int64_t UNKNOWN_FRAME_INTERVAL = -1;
+
explicit UiFrameInfoBuilder(int64_t* buffer) : mBuffer(buffer) {
memset(mBuffer, 0, UI_THREAD_FRAME_INFO_SIZE * sizeof(int64_t));
@@ -89,7 +93,7 @@
}
UiFrameInfoBuilder& setVsync(nsecs_t vsyncTime, nsecs_t intendedVsync,
- int64_t vsyncId, int64_t frameDeadline) {
+ int64_t vsyncId, int64_t frameDeadline, nsecs_t frameInterval) {
set(FrameInfoIndex::FrameTimelineVsyncId) = vsyncId;
set(FrameInfoIndex::Vsync) = vsyncTime;
set(FrameInfoIndex::IntendedVsync) = intendedVsync;
@@ -100,6 +104,7 @@
set(FrameInfoIndex::PerformTraversalsStart) = vsyncTime;
set(FrameInfoIndex::DrawStart) = vsyncTime;
set(FrameInfoIndex::FrameDeadline) = frameDeadline;
+ set(FrameInfoIndex::FrameInterval) = frameInterval;
return *this;
}
diff --git a/libs/hwui/FrameMetricsReporter.h b/libs/hwui/FrameMetricsReporter.h
index 3f2dc12..0ac025f 100644
--- a/libs/hwui/FrameMetricsReporter.h
+++ b/libs/hwui/FrameMetricsReporter.h
@@ -26,6 +26,7 @@
#include "FrameMetricsObserver.h"
#include <string.h>
+#include <mutex>
namespace android {
namespace uirenderer {
diff --git a/libs/hwui/JankTracker.cpp b/libs/hwui/JankTracker.cpp
index 4eefe92..7702f9b 100644
--- a/libs/hwui/JankTracker.cpp
+++ b/libs/hwui/JankTracker.cpp
@@ -95,27 +95,18 @@
// SF will begin composition at VSYNC-app + offsetDelta. If we are triple
// buffered, this is the expected time at which dequeueBuffer will
// return due to the staggering of VSYNC-app & VSYNC-sf.
- mDequeueTimeForgiveness = offsetDelta + 4_ms;
+ mDequeueTimeForgivenessLegacy = offsetDelta + 4_ms;
}
- setFrameInterval(frameIntervalNanos);
+ mFrameIntervalLegacy = frameIntervalNanos;
}
-void JankTracker::setFrameInterval(nsecs_t frameInterval) {
- mFrameInterval = frameInterval;
-
- for (auto& comparison : COMPARISONS) {
- mThresholds[comparison.type] = comparison.computeThreadshold(frameInterval);
- }
-}
-
-void JankTracker::finishFrame(const FrameInfo& frame) {
- std::lock_guard lock(mDataMutex);
-
+void JankTracker::calculateLegacyJank(FrameInfo& frame) {
// Fast-path for jank-free frames
int64_t totalDuration = frame.duration(sFrameStart, FrameInfoIndex::SwapBuffersCompleted);
- if (mDequeueTimeForgiveness && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
- nsecs_t expectedDequeueDuration = mDequeueTimeForgiveness + frame[FrameInfoIndex::Vsync] -
- frame[FrameInfoIndex::IssueDrawCommandsStart];
+ if (mDequeueTimeForgivenessLegacy && frame[FrameInfoIndex::DequeueBufferDuration] > 500_us) {
+ nsecs_t expectedDequeueDuration = mDequeueTimeForgivenessLegacy
+ + frame[FrameInfoIndex::Vsync]
+ - frame[FrameInfoIndex::IssueDrawCommandsStart];
if (expectedDequeueDuration > 0) {
// Forgive only up to the expected amount, but not more than
// the actual time spent blocked.
@@ -134,6 +125,56 @@
frame[FrameInfoIndex::IntendedVsync],
frame[FrameInfoIndex::GpuCompleted]);
+
+ // Only things like Surface.lockHardwareCanvas() are exempt from tracking
+ if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) {
+ return;
+ }
+
+ if (totalDuration > mFrameIntervalLegacy) {
+ mData->reportJankLegacy();
+ (*mGlobalData)->reportJankLegacy();
+ }
+
+ if (mSwapDeadlineLegacy < 0) {
+ mSwapDeadlineLegacy = frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy;
+ }
+ bool isTripleBuffered = (mSwapDeadlineLegacy - frame[FrameInfoIndex::IntendedVsync])
+ > (mFrameIntervalLegacy * 0.1);
+
+ mSwapDeadlineLegacy = std::max(mSwapDeadlineLegacy + mFrameIntervalLegacy,
+ frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy);
+
+ // If we hit the deadline, cool!
+ if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadlineLegacy
+ || totalDuration < mFrameIntervalLegacy) {
+ if (isTripleBuffered) {
+ mData->reportJankType(JankType::kHighInputLatency);
+ (*mGlobalData)->reportJankType(JankType::kHighInputLatency);
+ }
+ return;
+ }
+
+ mData->reportJankType(JankType::kMissedDeadlineLegacy);
+ (*mGlobalData)->reportJankType(JankType::kMissedDeadlineLegacy);
+
+ // Janked, reset the swap deadline
+ nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
+ nsecs_t lastFrameOffset = jitterNanos % mFrameIntervalLegacy;
+ mSwapDeadlineLegacy = frame[FrameInfoIndex::FrameCompleted]
+ - lastFrameOffset + mFrameIntervalLegacy;
+}
+
+void JankTracker::finishFrame(FrameInfo& frame, std::unique_ptr<FrameMetricsReporter>& reporter) {
+ std::lock_guard lock(mDataMutex);
+
+ calculateLegacyJank(frame);
+
+ // Fast-path for jank-free frames
+ int64_t totalDuration = frame.duration(FrameInfoIndex::IntendedVsync,
+ FrameInfoIndex::FrameCompleted);
+
+ LOG_ALWAYS_FATAL_IF(totalDuration <= 0, "Impossible totalDuration %" PRId64, totalDuration);
mData->reportFrame(totalDuration);
(*mGlobalData)->reportFrame(totalDuration);
@@ -142,55 +183,88 @@
return;
}
- if (totalDuration > mFrameInterval) {
- mData->reportJank();
- (*mGlobalData)->reportJank();
- }
+ int64_t frameInterval = frame[FrameInfoIndex::FrameInterval];
- if (mSwapDeadline < 0) {
- mSwapDeadline = frame[FrameInfoIndex::IntendedVsync] + mFrameInterval;
- }
- bool isTripleBuffered = (mSwapDeadline - frame[FrameInfoIndex::IntendedVsync]) > (mFrameInterval * 0.1);
+ // If we starter earlier than the intended frame start assuming an unstuffed scenario, it means
+ // that we are in a triple buffering situation.
+ bool isTripleBuffered = (mNextFrameStartUnstuffed - frame[FrameInfoIndex::IntendedVsync])
+ > (frameInterval * 0.1);
- mSwapDeadline = std::max(mSwapDeadline + mFrameInterval,
- frame[FrameInfoIndex::IntendedVsync] + mFrameInterval);
+ int64_t deadline = frame[FrameInfoIndex::FrameDeadline];
+
+ // If we are in triple buffering, we have enough buffers in queue to sustain a single frame
+ // drop without jank, so adjust the frame interval to the deadline.
+ if (isTripleBuffered) {
+ deadline += frameInterval;
+ frame.set(FrameInfoIndex::FrameDeadline) += frameInterval;
+ }
// If we hit the deadline, cool!
- if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) {
+ if (frame[FrameInfoIndex::GpuCompleted] < deadline) {
if (isTripleBuffered) {
mData->reportJankType(JankType::kHighInputLatency);
(*mGlobalData)->reportJankType(JankType::kHighInputLatency);
+
+ // Buffer stuffing state gets carried over to next frame, unless there is a "pause"
+ mNextFrameStartUnstuffed += frameInterval;
}
+ } else {
+ mData->reportJankType(JankType::kMissedDeadline);
+ (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
+ mData->reportJank();
+ (*mGlobalData)->reportJank();
+
+ // Janked, store the adjust deadline to detect triple buffering in next frame correctly.
+ nsecs_t jitterNanos = frame[FrameInfoIndex::GpuCompleted]
+ - frame[FrameInfoIndex::Vsync];
+ nsecs_t lastFrameOffset = jitterNanos % frameInterval;
+
+ // Note the time when the next frame would start in an unstuffed situation. If it starts
+ // earlier, we are in a stuffed situation.
+ mNextFrameStartUnstuffed = frame[FrameInfoIndex::GpuCompleted]
+ - lastFrameOffset + frameInterval;
+
+ recomputeThresholds(frameInterval);
+ for (auto& comparison : COMPARISONS) {
+ int64_t delta = frame.duration(comparison.start, comparison.end);
+ if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
+ mData->reportJankType(comparison.type);
+ (*mGlobalData)->reportJankType(comparison.type);
+ }
+ }
+
+ // Log daveys since they are weird and we don't know what they are (b/70339576)
+ if (totalDuration >= 700_ms) {
+ static int sDaveyCount = 0;
+ std::stringstream ss;
+ ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
+ for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
+ ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
+ }
+ ALOGI("%s", ss.str().c_str());
+ // Just so we have something that counts up, the value is largely irrelevant
+ ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
+ }
+ }
+
+ int64_t totalGPUDrawTime = frame.gpuDrawTime();
+ if (totalGPUDrawTime >= 0) {
+ mData->reportGPUFrame(totalGPUDrawTime);
+ (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
+ }
+
+ if (CC_UNLIKELY(reporter.get() != nullptr)) {
+ reporter->reportFrameMetrics(frame.data(), false /* hasPresentTime */);
+ }
+}
+
+void JankTracker::recomputeThresholds(int64_t frameBudget) {
+ if (mThresholdsFrameBudget == frameBudget) {
return;
}
-
- mData->reportJankType(JankType::kMissedDeadline);
- (*mGlobalData)->reportJankType(JankType::kMissedDeadline);
-
- // Janked, reset the swap deadline
- nsecs_t jitterNanos = frame[FrameInfoIndex::FrameCompleted] - frame[FrameInfoIndex::Vsync];
- nsecs_t lastFrameOffset = jitterNanos % mFrameInterval;
- mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval;
-
+ mThresholdsFrameBudget = frameBudget;
for (auto& comparison : COMPARISONS) {
- int64_t delta = frame.duration(comparison.start, comparison.end);
- if (delta >= mThresholds[comparison.type] && delta < IGNORE_EXCEEDING) {
- mData->reportJankType(comparison.type);
- (*mGlobalData)->reportJankType(comparison.type);
- }
- }
-
- // Log daveys since they are weird and we don't know what they are (b/70339576)
- if (totalDuration >= 700_ms) {
- static int sDaveyCount = 0;
- std::stringstream ss;
- ss << "Davey! duration=" << ns2ms(totalDuration) << "ms; ";
- for (size_t i = 0; i < static_cast<size_t>(FrameInfoIndex::NumIndexes); i++) {
- ss << FrameInfoNames[i] << "=" << frame[i] << ", ";
- }
- ALOGI("%s", ss.str().c_str());
- // Just so we have something that counts up, the value is largely irrelevant
- ATRACE_INT(ss.str().c_str(), ++sDaveyCount);
+ mThresholds[comparison.type] = comparison.computeThreadshold(frameBudget);
}
}
@@ -243,14 +317,5 @@
: FrameInfoIndex::IntendedVsync;
}
-void JankTracker::finishGpuDraw(const FrameInfo& frame) {
- std::lock_guard lock(mDataMutex);
- int64_t totalGPUDrawTime = frame.gpuDrawTime();
- if (totalGPUDrawTime >= 0) {
- mData->reportGPUFrame(totalGPUDrawTime);
- (*mGlobalData)->reportGPUFrame(totalGPUDrawTime);
- }
-}
-
} /* namespace uirenderer */
} /* namespace android */
diff --git a/libs/hwui/JankTracker.h b/libs/hwui/JankTracker.h
index 0964553..0d2574c 100644
--- a/libs/hwui/JankTracker.h
+++ b/libs/hwui/JankTracker.h
@@ -17,6 +17,7 @@
#define JANKTRACKER_H_
#include "FrameInfo.h"
+#include "FrameMetricsReporter.h"
#include "ProfileData.h"
#include "ProfileDataContainer.h"
#include "renderthread/TimeLord.h"
@@ -56,9 +57,11 @@
}
FrameInfo* startFrame() { return &mFrames.next(); }
- void finishFrame(const FrameInfo& frame);
- void finishGpuDraw(const FrameInfo& frame);
+ void finishFrame(FrameInfo& frame, std::unique_ptr<FrameMetricsReporter>& reporter);
+ // Calculates the 'legacy' jank information, i.e. with outdated refresh rate information and
+ // without GPU completion or deadlined information.
+ void calculateLegacyJank(FrameInfo& frame);
void dumpStats(int fd) { dumpData(fd, &mDescription, mData.get()); }
void dumpFrames(int fd);
void reset();
@@ -68,14 +71,16 @@
RingBuffer<FrameInfo, 120>& frames() { return mFrames; }
private:
- void setFrameInterval(nsecs_t frameIntervalNanos);
-
+ void recomputeThresholds(int64_t frameInterval);
static void dumpData(int fd, const ProfileDataDescription* description,
const ProfileData* data);
- std::array<int64_t, NUM_BUCKETS> mThresholds;
- int64_t mFrameInterval;
- nsecs_t mSwapDeadline = -1;
+ // Last frame budget for which mThresholds were computed.
+ int64_t mThresholdsFrameBudget GUARDED_BY(mDataMutex);
+ std::array<int64_t, NUM_BUCKETS> mThresholds GUARDED_BY(mDataMutex);
+
+ int64_t mFrameIntervalLegacy;
+ nsecs_t mSwapDeadlineLegacy = -1;
// The amount of time we will erase from the total duration to account
// for SF vsync offsets with HWC2 blocking dequeueBuffers.
// (Vsync + mDequeueBlockTolerance) is the point at which we expect
@@ -83,7 +88,9 @@
// point in time by comparing to (IssueDrawCommandsStart + DequeueDuration)
// This is only used if we are in pipelined mode and are using HWC2,
// otherwise it's 0.
- nsecs_t mDequeueTimeForgiveness = 0;
+ nsecs_t mDequeueTimeForgivenessLegacy = 0;
+
+ nsecs_t mNextFrameStartUnstuffed GUARDED_BY(mDataMutex) = -1;
ProfileDataContainer mData GUARDED_BY(mDataMutex);
ProfileDataContainer* mGlobalData GUARDED_BY(mDataMutex);
ProfileDataDescription mDescription;
diff --git a/libs/hwui/ProfileData.cpp b/libs/hwui/ProfileData.cpp
index a8e36e3..dd84396 100644
--- a/libs/hwui/ProfileData.cpp
+++ b/libs/hwui/ProfileData.cpp
@@ -24,7 +24,8 @@
static const char* JANK_TYPE_NAMES[] = {
"Missed Vsync", "High input latency", "Slow UI thread",
- "Slow bitmap uploads", "Slow issue draw commands", "Frame deadline missed"};
+ "Slow bitmap uploads", "Slow issue draw commands", "Frame deadline missed",
+ "Frame deadline missed (legacy)"};
// The bucketing algorithm controls so to speak
// If a frame is <= to this it goes in bucket 0
@@ -94,6 +95,8 @@
}
mJankFrameCount >>= divider;
mJankFrameCount += other.mJankFrameCount;
+ mJankLegacyFrameCount >>= divider;
+ mJankLegacyFrameCount += other.mJankLegacyFrameCount;
mTotalFrameCount >>= divider;
mTotalFrameCount += other.mTotalFrameCount;
if (mStatStartTime > other.mStatStartTime || mStatStartTime == 0) {
@@ -112,6 +115,9 @@
dprintf(fd, "\nJanky frames: %u (%.2f%%)", mJankFrameCount,
mTotalFrameCount == 0 ? 0.0f
: (float)mJankFrameCount / (float)mTotalFrameCount * 100.0f);
+ dprintf(fd, "\nJanky frames (legacy): %u (%.2f%%)", mJankLegacyFrameCount, mTotalFrameCount == 0
+ ? 0.0f
+ : (float)mJankLegacyFrameCount / (float)mTotalFrameCount * 100.0f);
dprintf(fd, "\n50th percentile: %ums", findPercentile(50));
dprintf(fd, "\n90th percentile: %ums", findPercentile(90));
dprintf(fd, "\n95th percentile: %ums", findPercentile(95));
@@ -158,6 +164,7 @@
mSlowFrameCounts.fill(0);
mTotalFrameCount = 0;
mJankFrameCount = 0;
+ mJankLegacyFrameCount = 0;
mStatStartTime = systemTime(SYSTEM_TIME_MONOTONIC);
mPipelineType = Properties::getRenderPipelineType();
}
diff --git a/libs/hwui/ProfileData.h b/libs/hwui/ProfileData.h
index dd3ba66..9be194c 100644
--- a/libs/hwui/ProfileData.h
+++ b/libs/hwui/ProfileData.h
@@ -35,6 +35,7 @@
kSlowSync,
kSlowRT,
kMissedDeadline,
+ kMissedDeadlineLegacy,
// must be last
NUM_BUCKETS,
@@ -60,10 +61,12 @@
void reportFrame(int64_t duration);
void reportGPUFrame(int64_t duration);
void reportJank() { mJankFrameCount++; }
+ void reportJankLegacy() { mJankLegacyFrameCount++; }
void reportJankType(JankType type) { mJankTypeCounts[static_cast<int>(type)]++; }
uint32_t totalFrameCount() const { return mTotalFrameCount; }
uint32_t jankFrameCount() const { return mJankFrameCount; }
+ uint32_t jankLegacyFrameCount() const { return mJankLegacyFrameCount; }
nsecs_t statsStartTime() const { return mStatStartTime; }
uint32_t jankTypeCount(JankType type) const { return mJankTypeCounts[static_cast<int>(type)]; }
RenderPipelineType pipelineType() const { return mPipelineType; }
@@ -104,6 +107,7 @@
uint32_t mTotalFrameCount;
uint32_t mJankFrameCount;
+ uint32_t mJankLegacyFrameCount;
nsecs_t mStatStartTime;
// true if HWUI renders with Vulkan pipeline
diff --git a/libs/hwui/jni/android_graphics_HardwareRenderer.cpp b/libs/hwui/jni/android_graphics_HardwareRenderer.cpp
index bd1da98..d859541 100644
--- a/libs/hwui/jni/android_graphics_HardwareRenderer.cpp
+++ b/libs/hwui/jni/android_graphics_HardwareRenderer.cpp
@@ -605,7 +605,8 @@
nsecs_t vsync = systemTime(SYSTEM_TIME_MONOTONIC);
UiFrameInfoBuilder(proxy.frameInfo())
.setVsync(vsync, vsync, UiFrameInfoBuilder::INVALID_VSYNC_ID,
- std::numeric_limits<int64_t>::max())
+ UiFrameInfoBuilder::UNKNOWN_DEADLINE,
+ UiFrameInfoBuilder::UNKNOWN_FRAME_INTERVAL)
.addFlag(FrameInfoFlags::SurfaceCanvas);
proxy.syncAndDrawFrame();
}
diff --git a/libs/hwui/renderthread/CanvasContext.cpp b/libs/hwui/renderthread/CanvasContext.cpp
index aedb5c2..b2a9863 100644
--- a/libs/hwui/renderthread/CanvasContext.cpp
+++ b/libs/hwui/renderthread/CanvasContext.cpp
@@ -473,6 +473,9 @@
return;
}
+ mCurrentFrameInfo->set(FrameInfoIndex::FrameInterval) =
+ mRenderThread.timeLord().frameIntervalNanos();
+
mCurrentFrameInfo->markIssueDrawCommandsStart();
Frame frame = mRenderPipeline->getFrame();
@@ -591,25 +594,13 @@
mCurrentFrameInfo->markFrameCompleted();
mCurrentFrameInfo->set(FrameInfoIndex::GpuCompleted)
= mCurrentFrameInfo->get(FrameInfoIndex::FrameCompleted);
- finishFrame(mCurrentFrameInfo);
+ mJankTracker.finishFrame(*mCurrentFrameInfo, mFrameMetricsReporter);
}
}
mRenderThread.cacheManager().onFrameCompleted();
}
-void CanvasContext::finishFrame(FrameInfo* frameInfo) {
- // TODO (b/169858044): Consolidate this into a single call.
- mJankTracker.finishFrame(*frameInfo);
- mJankTracker.finishGpuDraw(*frameInfo);
-
- // TODO (b/169858044): Move this into JankTracker to adjust deadline when queue is
- // double-stuffed.
- if (CC_UNLIKELY(mFrameMetricsReporter.get() != nullptr)) {
- mFrameMetricsReporter->reportFrameMetrics(frameInfo->data(), false /*hasPresentTime*/);
- }
-}
-
void CanvasContext::reportMetricsWithPresentTime() {
if (mFrameMetricsReporter == nullptr) {
return;
@@ -675,7 +666,7 @@
}
frameInfo->set(FrameInfoIndex::FrameCompleted) = gpuCompleteTime;
frameInfo->set(FrameInfoIndex::GpuCompleted) = gpuCompleteTime;
- instance->finishFrame(frameInfo);
+ instance->mJankTracker.finishFrame(*frameInfo, instance->mFrameMetricsReporter);
}
}
@@ -704,10 +695,11 @@
nsecs_t vsync = mRenderThread.timeLord().computeFrameTimeNanos();
int64_t vsyncId = mRenderThread.timeLord().lastVsyncId();
int64_t frameDeadline = mRenderThread.timeLord().lastFrameDeadline();
+ int64_t frameInterval = mRenderThread.timeLord().frameIntervalNanos();
int64_t frameInfo[UI_THREAD_FRAME_INFO_SIZE];
UiFrameInfoBuilder(frameInfo)
.addFlag(FrameInfoFlags::RTAnimation)
- .setVsync(vsync, vsync, vsyncId, frameDeadline);
+ .setVsync(vsync, vsync, vsyncId, frameDeadline, frameInterval);
TreeInfo info(TreeInfo::MODE_RT_ONLY, *this);
prepareTree(info, frameInfo, systemTime(SYSTEM_TIME_MONOTONIC), node);
diff --git a/libs/hwui/renderthread/DrawFrameTask.cpp b/libs/hwui/renderthread/DrawFrameTask.cpp
index 7a38a3b..cb92aa1 100644
--- a/libs/hwui/renderthread/DrawFrameTask.cpp
+++ b/libs/hwui/renderthread/DrawFrameTask.cpp
@@ -161,7 +161,9 @@
int64_t intendedVsync = mFrameInfo[static_cast<int>(FrameInfoIndex::IntendedVsync)];
int64_t vsyncId = mFrameInfo[static_cast<int>(FrameInfoIndex::FrameTimelineVsyncId)];
int64_t frameDeadline = mFrameInfo[static_cast<int>(FrameInfoIndex::FrameDeadline)];
- mRenderThread->timeLord().vsyncReceived(vsync, intendedVsync, vsyncId, frameDeadline);
+ int64_t frameInterval = mFrameInfo[static_cast<int>(FrameInfoIndex::FrameInterval)];
+ mRenderThread->timeLord().vsyncReceived(vsync, intendedVsync, vsyncId, frameDeadline,
+ frameInterval);
bool canDraw = mContext->makeCurrent();
mContext->unpinImages();
diff --git a/libs/hwui/renderthread/RenderThread.cpp b/libs/hwui/renderthread/RenderThread.cpp
index 79b9388..682baa6 100644
--- a/libs/hwui/renderthread/RenderThread.cpp
+++ b/libs/hwui/renderthread/RenderThread.cpp
@@ -87,9 +87,10 @@
RenderThread* rt = reinterpret_cast<RenderThread*>(data);
int64_t vsyncId = AChoreographer_getVsyncId(rt->mChoreographer);
int64_t frameDeadline = AChoreographer_getFrameDeadline(rt->mChoreographer);
+ int64_t frameInterval = AChoreographer_getFrameInterval(rt->mChoreographer);
rt->mVsyncRequested = false;
- if (rt->timeLord().vsyncReceived(frameTimeNanos, frameTimeNanos, vsyncId, frameDeadline) &&
- !rt->mFrameCallbackTaskPending) {
+ if (rt->timeLord().vsyncReceived(frameTimeNanos, frameTimeNanos, vsyncId, frameDeadline,
+ frameInterval) && !rt->mFrameCallbackTaskPending) {
ATRACE_NAME("queue mFrameCallbackTask");
rt->mFrameCallbackTaskPending = true;
nsecs_t runAt = (frameTimeNanos + rt->mDispatchFrameDelay);
diff --git a/libs/hwui/renderthread/TimeLord.cpp b/libs/hwui/renderthread/TimeLord.cpp
index abb6330..406066c 100644
--- a/libs/hwui/renderthread/TimeLord.cpp
+++ b/libs/hwui/renderthread/TimeLord.cpp
@@ -27,11 +27,14 @@
mFrameDeadline(std::numeric_limits<int64_t>::max()){}
bool TimeLord::vsyncReceived(nsecs_t vsync, nsecs_t intendedVsync, int64_t vsyncId,
- int64_t frameDeadline) {
+ int64_t frameDeadline, nsecs_t frameInterval) {
if (intendedVsync > mFrameIntendedTimeNanos) {
mFrameIntendedTimeNanos = intendedVsync;
mFrameVsyncId = vsyncId;
mFrameDeadline = frameDeadline;
+ if (frameInterval > 0) {
+ mFrameIntervalNanos = frameInterval;
+ }
}
if (vsync > mFrameTimeNanos) {
diff --git a/libs/hwui/renderthread/TimeLord.h b/libs/hwui/renderthread/TimeLord.h
index fa05c030..8cd6733 100644
--- a/libs/hwui/renderthread/TimeLord.h
+++ b/libs/hwui/renderthread/TimeLord.h
@@ -33,7 +33,7 @@
// returns true if the vsync is newer, false if it was rejected for staleness
bool vsyncReceived(nsecs_t vsync, nsecs_t indendedVsync, int64_t vsyncId,
- int64_t frameDeadline);
+ int64_t frameDeadline, nsecs_t frameInterval);
nsecs_t latestVsync() { return mFrameTimeNanos; }
nsecs_t computeFrameTimeNanos();
int64_t lastVsyncId() const { return mFrameVsyncId; }
diff --git a/libs/hwui/tests/macrobench/TestSceneRunner.cpp b/libs/hwui/tests/macrobench/TestSceneRunner.cpp
index 8c7d261..13ac367 100644
--- a/libs/hwui/tests/macrobench/TestSceneRunner.cpp
+++ b/libs/hwui/tests/macrobench/TestSceneRunner.cpp
@@ -146,7 +146,9 @@
testContext.waitForVsync();
nsecs_t vsync = systemTime(SYSTEM_TIME_MONOTONIC);
UiFrameInfoBuilder(proxy->frameInfo())
- .setVsync(vsync, vsync, UiFrameInfoBuilder::INVALID_VSYNC_ID, std::numeric_limits<int64_t>::max());
+ .setVsync(vsync, vsync, UiFrameInfoBuilder::INVALID_VSYNC_ID,
+ UiFrameInfoBuilder::UNKNOWN_DEADLINE,
+ UiFrameInfoBuilder::UNKNOWN_FRAME_INTERVAL);
proxy->syncAndDrawFrame();
}
@@ -162,7 +164,9 @@
{
ATRACE_NAME("UI-Draw Frame");
UiFrameInfoBuilder(proxy->frameInfo())
- .setVsync(vsync, vsync, UiFrameInfoBuilder::INVALID_VSYNC_ID, std::numeric_limits<int64_t>::max());
+ .setVsync(vsync, vsync, UiFrameInfoBuilder::INVALID_VSYNC_ID,
+ UiFrameInfoBuilder::UNKNOWN_DEADLINE,
+ UiFrameInfoBuilder::UNKNOWN_FRAME_INTERVAL);
scene->doFrame(i);
proxy->syncAndDrawFrame();
}
diff --git a/libs/hwui/tests/unit/JankTrackerTests.cpp b/libs/hwui/tests/unit/JankTrackerTests.cpp
new file mode 100644
index 0000000..f467ebf
--- /dev/null
+++ b/libs/hwui/tests/unit/JankTrackerTests.cpp
@@ -0,0 +1,182 @@
+/*
+ * Copyright (C) 2021 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <gtest/gtest.h>
+#include <gmock/gmock.h>
+
+#include <JankTracker.h>
+#include <utils/TimeUtils.h>
+
+using namespace android;
+using namespace android::uirenderer;
+
+class TestFrameMetricsObserver : public FrameMetricsObserver {
+public:
+ void notify(const int64_t*) {}
+};
+
+TEST(JankTracker, noJank) {
+ std::mutex mutex;
+ ProfileDataContainer container(mutex);
+ JankTracker jankTracker(&container);
+ std::unique_ptr<FrameMetricsReporter> reporter = std::make_unique<FrameMetricsReporter>();
+
+ FrameInfo* info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 100_ms;
+ info->set(FrameInfoIndex::Vsync) = 101_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 115_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 115_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 115_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 120_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 116_ms;
+ info->set(FrameInfoIndex::Vsync) = 117_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 129_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 131_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 131_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 136_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(2, container.get()->totalFrameCount());
+ ASSERT_EQ(0, container.get()->jankFrameCount());
+}
+
+
+TEST(JankTracker, jank) {
+ std::mutex mutex;
+ ProfileDataContainer container(mutex);
+ JankTracker jankTracker(&container);
+ std::unique_ptr<FrameMetricsReporter> reporter = std::make_unique<FrameMetricsReporter>();
+
+ FrameInfo* info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 100_ms;
+ info->set(FrameInfoIndex::Vsync) = 101_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 115_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 120_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(1, container.get()->totalFrameCount());
+ ASSERT_EQ(1, container.get()->jankFrameCount());
+}
+
+TEST(JankTracker, legacyJankButNoRealJank) {
+ std::mutex mutex;
+ ProfileDataContainer container(mutex);
+ JankTracker jankTracker(&container);
+ std::unique_ptr<FrameMetricsReporter> reporter = std::make_unique<FrameMetricsReporter>();
+
+ FrameInfo* info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 100_ms;
+ info->set(FrameInfoIndex::Vsync) = 101_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 117_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 118_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 118_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 120_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(1, container.get()->totalFrameCount());
+ ASSERT_EQ(0, container.get()->jankFrameCount());
+ ASSERT_EQ(1, container.get()->jankLegacyFrameCount());
+}
+
+TEST(JankTracker, doubleStuffed) {
+ std::mutex mutex;
+ ProfileDataContainer container(mutex);
+ JankTracker jankTracker(&container);
+ std::unique_ptr<FrameMetricsReporter> reporter = std::make_unique<FrameMetricsReporter>();
+
+ // First frame janks
+ FrameInfo* info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 100_ms;
+ info->set(FrameInfoIndex::Vsync) = 101_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 115_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 120_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(1, container.get()->jankFrameCount());
+
+ // Second frame is long, but doesn't jank because double-stuffed.
+ info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 116_ms;
+ info->set(FrameInfoIndex::Vsync) = 122_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 129_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 137_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 137_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 136_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(2, container.get()->totalFrameCount());
+ ASSERT_EQ(1, container.get()->jankFrameCount());
+}
+
+TEST(JankTracker, doubleStuffedThenPauseThenJank) {
+ std::mutex mutex;
+ ProfileDataContainer container(mutex);
+ JankTracker jankTracker(&container);
+ std::unique_ptr<FrameMetricsReporter> reporter = std::make_unique<FrameMetricsReporter>();
+
+ // First frame janks
+ FrameInfo* info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 100_ms;
+ info->set(FrameInfoIndex::Vsync) = 101_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 115_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 121_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 120_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(1, container.get()->jankFrameCount());
+
+ // Second frame is long, but doesn't jank because double-stuffed.
+ info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 116_ms;
+ info->set(FrameInfoIndex::Vsync) = 122_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 129_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 137_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 137_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 136_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(1, container.get()->jankFrameCount());
+
+ // Thirdframe is long and skips one frame some double stuffed logic gets reset
+ info = jankTracker.startFrame();
+ info->set(FrameInfoIndex::IntendedVsync) = 148_ms;
+ info->set(FrameInfoIndex::Vsync) = 148_ms;
+ info->set(FrameInfoIndex::SwapBuffersCompleted) = 160_ms;
+ info->set(FrameInfoIndex::GpuCompleted) = 169_ms;
+ info->set(FrameInfoIndex::FrameCompleted) = 169_ms;
+ info->set(FrameInfoIndex::FrameInterval) = 16_ms;
+ info->set(FrameInfoIndex::FrameDeadline) = 168_ms;
+ jankTracker.finishFrame(*info, reporter);
+
+ ASSERT_EQ(3, container.get()->totalFrameCount());
+ ASSERT_EQ(2, container.get()->jankFrameCount());
+}
\ No newline at end of file