diff options
author | Jorim Jaggi <jjaggi@google.com> | 2021-01-19 00:08:02 +0100 |
---|---|---|
committer | Jorim Jaggi <jjaggi@google.com> | 2021-04-13 15:18:27 +0000 |
commit | 10f328c580fe1e897b51a7e4b38ee4c341d970f1 (patch) | |
tree | b5719df2aa8460ef2925440e72ecec07020557b1 | |
parent | a373e1ed5a59997b2cc8ac86615963d8597e4a2b (diff) |
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
22 files changed, 437 insertions, 135 deletions
diff --git a/core/java/android/view/Choreographer.java b/core/java/android/view/Choreographer.java index 7b3a8a64fc37..0a3963d782b1 100644 --- a/core/java/android/view/Choreographer.java +++ b/core/java/android/view/Choreographer.java @@ -177,8 +177,14 @@ public final class Choreographer { private boolean mCallbacksRunning; @UnsupportedAppUsage private long mLastFrameTimeNanos; - @UnsupportedAppUsage + + /** DO NOT USE since this will not updated when screen refresh changes. */ + @UnsupportedAppUsage(maxTargetSdk = Build.VERSION_CODES.R, + publicAlternatives = "Use {@link android.view.Display#getRefreshRate} instead") + @Deprecated private long mFrameIntervalNanos; + private long mLastFrameIntervalNanos; + private boolean mDebugPrintNextFrameTimeDelta; private int mFPSDivisor = 1; private DisplayEventReceiver.VsyncEventData mLastVsyncEventData = @@ -392,7 +398,9 @@ public final class Choreographer { * @hide */ public long getFrameIntervalNanos() { - return mFrameIntervalNanos; + synchronized (mLock) { + return mLastFrameIntervalNanos; + } } void dump(String prefix, PrintWriter writer) { @@ -688,6 +696,7 @@ public final class Choreographer { void doFrame(long frameTimeNanos, int frame, DisplayEventReceiver.VsyncEventData vsyncEventData) { final long startNanos; + final long frameIntervalNanos = vsyncEventData.frameInterval; synchronized (mLock) { if (!mFrameScheduled) { return; // no work to do @@ -702,17 +711,17 @@ public final class Choreographer { long intendedFrameTimeNanos = frameTimeNanos; startNanos = System.nanoTime(); final long jitterNanos = startNanos - frameTimeNanos; - if (jitterNanos >= mFrameIntervalNanos) { - final long skippedFrames = jitterNanos / mFrameIntervalNanos; + if (jitterNanos >= frameIntervalNanos) { + final long skippedFrames = jitterNanos / frameIntervalNanos; if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) { Log.i(TAG, "Skipped " + skippedFrames + " frames! " + "The application may be doing too much work on its main thread."); } - final long lastFrameOffset = jitterNanos % mFrameIntervalNanos; + final long lastFrameOffset = jitterNanos % frameIntervalNanos; if (DEBUG_JANK) { Log.d(TAG, "Missed vsync by " + (jitterNanos * 0.000001f) + " ms " + "which is more than the frame interval of " - + (mFrameIntervalNanos * 0.000001f) + " ms! " + + (frameIntervalNanos * 0.000001f) + " ms! " + "Skipping " + skippedFrames + " frames and setting frame " + "time to " + (lastFrameOffset * 0.000001f) + " ms in the past."); } @@ -730,16 +739,17 @@ public final class Choreographer { if (mFPSDivisor > 1) { long timeSinceVsync = frameTimeNanos - mLastFrameTimeNanos; - if (timeSinceVsync < (mFrameIntervalNanos * mFPSDivisor) && timeSinceVsync > 0) { + if (timeSinceVsync < (frameIntervalNanos * mFPSDivisor) && timeSinceVsync > 0) { scheduleVsyncLocked(); return; } } mFrameInfo.setVsync(intendedFrameTimeNanos, frameTimeNanos, vsyncEventData.id, - vsyncEventData.frameDeadline, startNanos); + vsyncEventData.frameDeadline, startNanos, vsyncEventData.frameInterval); mFrameScheduled = false; mLastFrameTimeNanos = frameTimeNanos; + mLastFrameIntervalNanos = frameIntervalNanos; mLastVsyncEventData = vsyncEventData; } @@ -751,16 +761,17 @@ public final class Choreographer { AnimationUtils.lockAnimationClock(frameTimeNanos / TimeUtils.NANOS_PER_MS); mFrameInfo.markInputHandlingStart(); - doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos); + doCallbacks(Choreographer.CALLBACK_INPUT, frameTimeNanos, frameIntervalNanos); mFrameInfo.markAnimationsStart(); - doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos); - doCallbacks(Choreographer.CALLBACK_INSETS_ANIMATION, frameTimeNanos); + doCallbacks(Choreographer.CALLBACK_ANIMATION, frameTimeNanos, frameIntervalNanos); + doCallbacks(Choreographer.CALLBACK_INSETS_ANIMATION, frameTimeNanos, + frameIntervalNanos); mFrameInfo.markPerformTraversalsStart(); - doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos); + doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos, frameIntervalNanos); - doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos); + doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos, frameIntervalNanos); } finally { AnimationUtils.unlockAnimationClock(); Trace.traceEnd(Trace.TRACE_TAG_VIEW); @@ -774,7 +785,7 @@ public final class Choreographer { } } - void doCallbacks(int callbackType, long frameTimeNanos) { + void doCallbacks(int callbackType, long frameTimeNanos, long frameIntervalNanos) { CallbackRecord callbacks; synchronized (mLock) { // We use "now" to determine when callbacks become due because it's possible @@ -799,13 +810,13 @@ public final class Choreographer { if (callbackType == Choreographer.CALLBACK_COMMIT) { final long jitterNanos = now - frameTimeNanos; Trace.traceCounter(Trace.TRACE_TAG_VIEW, "jitterNanos", (int) jitterNanos); - if (jitterNanos >= 2 * mFrameIntervalNanos) { - final long lastFrameOffset = jitterNanos % mFrameIntervalNanos - + mFrameIntervalNanos; + if (jitterNanos >= 2 * frameIntervalNanos) { + final long lastFrameOffset = jitterNanos % frameIntervalNanos + + frameIntervalNanos; if (DEBUG_JANK) { Log.d(TAG, "Commit callback delayed by " + (jitterNanos * 0.000001f) + " ms which is more than twice the frame interval of " - + (mFrameIntervalNanos * 0.000001f) + " ms! " + + (frameIntervalNanos * 0.000001f) + " ms! " + "Setting frame time to " + (lastFrameOffset * 0.000001f) + " ms in the past."); mDebugPrintNextFrameTimeDelta = true; diff --git a/core/java/android/view/DisplayEventReceiver.java b/core/java/android/view/DisplayEventReceiver.java index e6cd25275ca2..e3f430bf3fe0 100644 --- a/core/java/android/view/DisplayEventReceiver.java +++ b/core/java/android/view/DisplayEventReceiver.java @@ -158,14 +158,23 @@ public abstract class DisplayEventReceiver { // allotted for the frame to be completed. public final long frameDeadline; - VsyncEventData(long id, long frameDeadline) { + /** + * The current interval between frames in ns. This will be used to align + * {@link FrameInfo#VSYNC} to the current vsync in case Choreographer callback was heavily + * delayed by the app. + */ + public final long frameInterval; + + VsyncEventData(long id, long frameDeadline, long frameInterval) { this.id = id; this.frameDeadline = frameDeadline; + this.frameInterval = frameInterval; } VsyncEventData() { this.id = FrameInfo.INVALID_VSYNC_ID; this.frameDeadline = Long.MAX_VALUE; + this.frameInterval = -1; } } @@ -259,9 +268,9 @@ public abstract class DisplayEventReceiver { // Called from native code. @SuppressWarnings("unused") private void dispatchVsync(long timestampNanos, long physicalDisplayId, int frame, - long frameTimelineVsyncId, long frameDeadline) { + long frameTimelineVsyncId, long frameDeadline, long frameInterval) { onVsync(timestampNanos, physicalDisplayId, frame, - new VsyncEventData(frameTimelineVsyncId, frameDeadline)); + new VsyncEventData(frameTimelineVsyncId, frameDeadline, frameInterval)); } // Called from native code. diff --git a/core/java/android/view/FrameMetrics.java b/core/java/android/view/FrameMetrics.java index 9cdf91a55c39..f6d525c10cc9 100644 --- a/core/java/android/view/FrameMetrics.java +++ b/core/java/android/view/FrameMetrics.java @@ -243,18 +243,19 @@ public final class FrameMetrics { int DRAW_START = 8; int FRAME_DEADLINE = 9; int FRAME_START_TIME = 10; - int SYNC_QUEUED = 11; - int SYNC_START = 12; - int ISSUE_DRAW_COMMANDS_START = 13; - int SWAP_BUFFERS = 14; - int FRAME_COMPLETED = 15; - int DEQUEUE_BUFFER_DURATION = 16; - int QUEUE_BUFFER_DURATION = 17; - int GPU_COMPLETED = 18; - int SWAP_BUFFERS_COMPLETED = 19; - int DISPLAY_PRESENT_TIME = 20; + int FRAME_INTERVAL = 11; + int SYNC_QUEUED = 12; + int SYNC_START = 13; + int ISSUE_DRAW_COMMANDS_START = 14; + int SWAP_BUFFERS = 15; + int FRAME_COMPLETED = 16; + int DEQUEUE_BUFFER_DURATION = 17; + int QUEUE_BUFFER_DURATION = 18; + int GPU_COMPLETED = 19; + int SWAP_BUFFERS_COMPLETED = 20; + int DISPLAY_PRESENT_TIME = 21; - int FRAME_STATS_COUNT = 21; // must always be last and in sync with + int FRAME_STATS_COUNT = 22; // must always be last and in sync with // FrameInfoIndex::NumIndexes in libs/hwui/FrameInfo.h } diff --git a/core/jni/android_view_DisplayEventReceiver.cpp b/core/jni/android_view_DisplayEventReceiver.cpp index 8977b97fc541..ce772cf9faff 100644 --- a/core/jni/android_view_DisplayEventReceiver.cpp +++ b/core/jni/android_view_DisplayEventReceiver.cpp @@ -107,7 +107,7 @@ void NativeDisplayEventReceiver::dispatchVsync(nsecs_t timestamp, PhysicalDispla ALOGV("receiver %p ~ Invoking vsync handler.", this); env->CallVoidMethod(receiverObj.get(), gDisplayEventReceiverClassInfo.dispatchVsync, timestamp, displayId.value, count, vsyncEventData.id, - vsyncEventData.deadlineTimestamp); + vsyncEventData.deadlineTimestamp, vsyncEventData.frameInterval); ALOGV("receiver %p ~ Returned from vsync handler.", this); } @@ -239,7 +239,7 @@ int register_android_view_DisplayEventReceiver(JNIEnv* env) { gDisplayEventReceiverClassInfo.dispatchVsync = GetMethodIDOrDie(env, gDisplayEventReceiverClassInfo.clazz, "dispatchVsync", - "(JJIJJ)V"); + "(JJIJJJ)V"); gDisplayEventReceiverClassInfo.dispatchHotplug = GetMethodIDOrDie(env, gDisplayEventReceiverClassInfo.clazz, "dispatchHotplug", "(JJZ)V"); gDisplayEventReceiverClassInfo.dispatchModeChanged = diff --git a/graphics/java/android/graphics/FrameInfo.java b/graphics/java/android/graphics/FrameInfo.java index 786c03ba5150..b9393fff8896 100644 --- a/graphics/java/android/graphics/FrameInfo.java +++ b/graphics/java/android/graphics/FrameInfo.java @@ -90,19 +90,23 @@ public final class FrameInfo { // When frame actually started. public static final int FRAME_START_TIME = 10; + // Interval between two consecutive frames + public static final int FRAME_INTERVAL = 11; + // Must be the last one // This value must be in sync with `UI_THREAD_FRAME_INFO_SIZE` in FrameInfo.h - private static final int FRAME_INFO_SIZE = FRAME_START_TIME + 1; + private static final int FRAME_INFO_SIZE = FRAME_INTERVAL + 1; /** checkstyle */ public void setVsync(long intendedVsync, long usedVsync, long frameTimelineVsyncId, - long frameDeadline, long frameStartTime) { + long frameDeadline, long frameStartTime, long frameInterval) { frameInfo[FRAME_TIMELINE_VSYNC_ID] = frameTimelineVsyncId; frameInfo[INTENDED_VSYNC] = intendedVsync; frameInfo[VSYNC] = usedVsync; frameInfo[FLAGS] = 0; frameInfo[FRAME_DEADLINE] = frameDeadline; frameInfo[FRAME_START_TIME] = frameStartTime; + frameInfo[FRAME_INTERVAL] = frameInterval; } /** checkstyle */ diff --git a/graphics/java/android/graphics/HardwareRenderer.java b/graphics/java/android/graphics/HardwareRenderer.java index 7589435fc3b7..f3dba82287ab 100644 --- a/graphics/java/android/graphics/HardwareRenderer.java +++ b/graphics/java/android/graphics/HardwareRenderer.java @@ -367,7 +367,7 @@ public class HardwareRenderer { public @NonNull FrameRenderRequest setVsyncTime(long vsyncTime) { // TODO(b/168552873): populate vsync Id once available to Choreographer public API mFrameInfo.setVsync(vsyncTime, vsyncTime, FrameInfo.INVALID_VSYNC_ID, Long.MAX_VALUE, - vsyncTime); + vsyncTime, -1); mFrameInfo.addFlags(FrameInfo.FLAG_SURFACE_CANVAS); return this; } diff --git a/libs/hwui/Android.bp b/libs/hwui/Android.bp index 9270901bcacd..f2c48bb8d2bc 100644 --- a/libs/hwui/Android.bp +++ b/libs/hwui/Android.bp @@ -653,6 +653,7 @@ cc_test { "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 51fbf363f51c..fecf26906c04 100644 --- a/libs/hwui/FrameInfo.cpp +++ b/libs/hwui/FrameInfo.cpp @@ -21,16 +21,18 @@ namespace android { 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 62ac4ca5fdad..2a134fa214e7 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 @@ enum class FrameInfoIndex { DrawStart, FrameDeadline, FrameStartTime, + FrameInterval, // End of UI frame info SyncQueued, @@ -77,6 +78,9 @@ enum { 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 @@ public: } 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 @@ public: 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 3f2dc1244085..0ac025fb01db 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 4eefe921fbe9..7702f9bba0e4 100644 --- a/libs/hwui/JankTracker.cpp +++ b/libs/hwui/JankTracker.cpp @@ -95,27 +95,18 @@ JankTracker::JankTracker(ProfileDataContainer* globalData) // 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,29 +125,29 @@ void JankTracker::finishFrame(const FrameInfo& frame) { frame[FrameInfoIndex::IntendedVsync], frame[FrameInfoIndex::GpuCompleted]); - mData->reportFrame(totalDuration); - (*mGlobalData)->reportFrame(totalDuration); // Only things like Surface.lockHardwareCanvas() are exempt from tracking if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) { return; } - if (totalDuration > mFrameInterval) { - mData->reportJank(); - (*mGlobalData)->reportJank(); + if (totalDuration > mFrameIntervalLegacy) { + mData->reportJankLegacy(); + (*mGlobalData)->reportJankLegacy(); } - if (mSwapDeadline < 0) { - mSwapDeadline = frame[FrameInfoIndex::IntendedVsync] + mFrameInterval; + if (mSwapDeadlineLegacy < 0) { + mSwapDeadlineLegacy = frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy; } - bool isTripleBuffered = (mSwapDeadline - frame[FrameInfoIndex::IntendedVsync]) > (mFrameInterval * 0.1); + bool isTripleBuffered = (mSwapDeadlineLegacy - frame[FrameInfoIndex::IntendedVsync]) + > (mFrameIntervalLegacy * 0.1); - mSwapDeadline = std::max(mSwapDeadline + mFrameInterval, - frame[FrameInfoIndex::IntendedVsync] + mFrameInterval); + mSwapDeadlineLegacy = std::max(mSwapDeadlineLegacy + mFrameIntervalLegacy, + frame[FrameInfoIndex::IntendedVsync] + mFrameIntervalLegacy); // If we hit the deadline, cool! - if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadline || totalDuration < mFrameInterval) { + if (frame[FrameInfoIndex::FrameCompleted] < mSwapDeadlineLegacy + || totalDuration < mFrameIntervalLegacy) { if (isTripleBuffered) { mData->reportJankType(JankType::kHighInputLatency); (*mGlobalData)->reportJankType(JankType::kHighInputLatency); @@ -164,33 +155,116 @@ void JankTracker::finishFrame(const FrameInfo& frame) { return; } - mData->reportJankType(JankType::kMissedDeadline); - (*mGlobalData)->reportJankType(JankType::kMissedDeadline); + 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 % mFrameInterval; - mSwapDeadline = frame[FrameInfoIndex::FrameCompleted] - lastFrameOffset + mFrameInterval; + nsecs_t lastFrameOffset = jitterNanos % mFrameIntervalLegacy; + mSwapDeadlineLegacy = frame[FrameInfoIndex::FrameCompleted] + - lastFrameOffset + mFrameIntervalLegacy; +} - 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); - } +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); + + // Only things like Surface.lockHardwareCanvas() are exempt from tracking + if (CC_UNLIKELY(frame[FrameInfoIndex::Flags] & EXEMPT_FRAMES_FLAGS)) { + return; + } + + int64_t frameInterval = frame[FrameInfoIndex::FrameInterval]; + + // 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); + + 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; } - // 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] << ", "; + // If we hit the deadline, cool! + 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); } - 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; + } + mThresholdsFrameBudget = frameBudget; + for (auto& comparison : COMPARISONS) { + mThresholds[comparison.type] = comparison.computeThreadshold(frameBudget); } } @@ -243,14 +317,5 @@ void JankTracker::reset() { : 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 096455372923..0d2574cb8640 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 @@ public: } 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 @@ public: 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 @@ private: // 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 a8e36e37905d..dd8439647fd3 100644 --- a/libs/hwui/ProfileData.cpp +++ b/libs/hwui/ProfileData.cpp @@ -24,7 +24,8 @@ namespace uirenderer { 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 @@ void ProfileData::mergeWith(const ProfileData& other) { } 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 @@ void ProfileData::dump(int fd) const { 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 @@ void ProfileData::reset() { 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 dd3ba661dd29..9be194c952e1 100644 --- a/libs/hwui/ProfileData.h +++ b/libs/hwui/ProfileData.h @@ -35,6 +35,7 @@ enum JankType { kSlowSync, kSlowRT, kMissedDeadline, + kMissedDeadlineLegacy, // must be last NUM_BUCKETS, @@ -60,10 +61,12 @@ public: 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 @@ private: 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 bd1da985a33e..d85954116dd1 100644 --- a/libs/hwui/jni/android_graphics_HardwareRenderer.cpp +++ b/libs/hwui/jni/android_graphics_HardwareRenderer.cpp @@ -605,7 +605,8 @@ static jobject android_view_ThreadedRenderer_createHardwareBitmapFromRenderNode( 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 aedb5c28dc3e..b2a986361b87 100644 --- a/libs/hwui/renderthread/CanvasContext.cpp +++ b/libs/hwui/renderthread/CanvasContext.cpp @@ -473,6 +473,9 @@ void CanvasContext::draw() { return; } + mCurrentFrameInfo->set(FrameInfoIndex::FrameInterval) = + mRenderThread.timeLord().frameIntervalNanos(); + mCurrentFrameInfo->markIssueDrawCommandsStart(); Frame frame = mRenderPipeline->getFrame(); @@ -591,25 +594,13 @@ void CanvasContext::draw() { 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 @@ void CanvasContext::onSurfaceStatsAvailable(void* context, ASurfaceControl* cont } frameInfo->set(FrameInfoIndex::FrameCompleted) = gpuCompleteTime; frameInfo->set(FrameInfoIndex::GpuCompleted) = gpuCompleteTime; - instance->finishFrame(frameInfo); + instance->mJankTracker.finishFrame(*frameInfo, instance->mFrameMetricsReporter); } } @@ -704,10 +695,11 @@ void CanvasContext::prepareAndDraw(RenderNode* node) { 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 7a38a3bc9c05..cb92aa191073 100644 --- a/libs/hwui/renderthread/DrawFrameTask.cpp +++ b/libs/hwui/renderthread/DrawFrameTask.cpp @@ -161,7 +161,9 @@ bool DrawFrameTask::syncFrameState(TreeInfo& info) { 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 79b938841bc2..682baa60a207 100644 --- a/libs/hwui/renderthread/RenderThread.cpp +++ b/libs/hwui/renderthread/RenderThread.cpp @@ -87,9 +87,10 @@ void RenderThread::frameCallback(int64_t frameTimeNanos, void* data) { 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 abb633028363..406066c92bab 100644 --- a/libs/hwui/renderthread/TimeLord.cpp +++ b/libs/hwui/renderthread/TimeLord.cpp @@ -27,11 +27,14 @@ TimeLord::TimeLord() : mFrameIntervalNanos(milliseconds_to_nanoseconds(16)), 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 fa05c030fa0f..8cd6733c1cde 100644 --- a/libs/hwui/renderthread/TimeLord.h +++ b/libs/hwui/renderthread/TimeLord.h @@ -33,7 +33,7 @@ public: // 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 8c7d2612f39b..13ac3671c9c7 100644 --- a/libs/hwui/tests/macrobench/TestSceneRunner.cpp +++ b/libs/hwui/tests/macrobench/TestSceneRunner.cpp @@ -146,7 +146,9 @@ void run(const TestScene::Info& info, const TestScene::Options& opts, 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 @@ void run(const TestScene::Info& info, const TestScene::Options& opts, { 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 000000000000..f467ebf5d888 --- /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 |