Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Change hwui jank detection to use deadline & gpu completion (1/2)" into sc-dev

Browse Source
This commit is contained in:
Jorim Jaggi
2021-04-13 19:58:27 +00:00
committed by Android (Google) Code Review
parent b8a744543c 10f328c580
commit 21142c13de
22 changed files with 444 additions and 142 deletions
Download Patch File Download Diff File Expand all files Collapse all files

47
core/java/android/view/Choreographer.java
View File

@@ -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;

15
core/java/android/view/DisplayEventReceiver.java
View File

@@ -146,14 +146,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;
}
}
@@ -247,9 +256,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.

23
core/java/android/view/FrameMetrics.java
View File

@@ -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
}

4
core/jni/android_view_DisplayEventReceiver.cpp
View File

@@ -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 =

8
graphics/java/android/graphics/FrameInfo.java
View File

@@ -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 */

2
graphics/java/android/graphics/HardwareRenderer.java
View File

@@ -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;
}

1
libs/hwui/Android.bp
View File

@@ -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",

18
libs/hwui/FrameInfo.cpp
View File

@@ -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) {

9
libs/hwui/FrameInfo.h
View File

@@ -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;
}

1
libs/hwui/FrameMetricsReporter.h
View File

@@ -26,6 +26,7 @@
#include "FrameMetricsObserver.h"
#include <string.h>
#include <mutex>
namespace android {
namespace uirenderer {

191
libs/hwui/JankTracker.cpp
View File

@@ -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,6 +125,56 @@ void JankTracker::finishFrame(const FrameInfo& frame) {
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 @@ void JankTracker::finishFrame(const FrameInfo& frame) {
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 @@ 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 */

23
libs/hwui/JankTracker.h
View File

@@ -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;

9
libs/hwui/ProfileData.cpp
View File

@@ -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();
}

4
libs/hwui/ProfileData.h
View File

@@ -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

3
libs/hwui/jni/android_graphics_HardwareRenderer.cpp
View File

@@ -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();
}

22
libs/hwui/renderthread/CanvasContext.cpp
View File

@@ -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);

4
libs/hwui/renderthread/DrawFrameTask.cpp
View File

@@ -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();

5
libs/hwui/renderthread/RenderThread.cpp
View File

@@ -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);

5
libs/hwui/renderthread/TimeLord.cpp
View File

@@ -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) {

2
libs/hwui/renderthread/TimeLord.h
View File

@@ -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; }

8
libs/hwui/tests/macrobench/TestSceneRunner.cpp
View File

@@ -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();
}

182
libs/hwui/tests/unit/JankTrackerTests.cpp Normal file
View File

@@ -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());
}