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

Merge "Fix overcounting after end in case of incomplete callbacks" into tm-dev

Browse Source
This commit is contained in:
Jorim Jaggi
2022-03-31 00:07:42 +00:00
committed by Android (Google) Code Review
parent 3bea7df55b 7e9b844f52
commit cd106a5aa7
4 changed files with 164 additions and 35 deletions
Download Patch File Download Diff File Expand all files Collapse all files

58
core/java/com/android/internal/jank/FrameTracker.java
View File

@@ -36,6 +36,7 @@ import android.os.Trace;
import android.text.TextUtils;
import android.util.Log;
import android.util.SparseArray;
import android.util.StatsLog;
import android.view.Choreographer;
import android.view.FrameMetrics;
import android.view.SurfaceControl;
@@ -98,6 +99,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
private final ViewRootImpl.SurfaceChangedCallback mSurfaceChangedCallback;
private final Handler mHandler;
private final ChoreographerWrapper mChoreographer;
private final StatsLogWrapper mStatsLog;
private final Object mLock = InteractionJankMonitor.getInstance().getLock();
private final boolean mDeferMonitoring;
@@ -148,6 +150,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
@NonNull SurfaceControlWrapper surfaceControlWrapper,
@NonNull ChoreographerWrapper choreographer,
@Nullable FrameMetricsWrapper metrics,
@NonNull StatsLogWrapper statsLog,
int traceThresholdMissedFrames, int traceThresholdFrameTimeMillis,
@Nullable FrameTrackerListener listener, @NonNull Configuration config) {
mSurfaceOnly = config.isSurfaceOnly();
@@ -155,6 +158,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
mHandler = handler;
mChoreographer = choreographer;
mSurfaceControlWrapper = surfaceControlWrapper;
mStatsLog = statsLog;
mDeferMonitoring = config.shouldDeferMonitor();
// HWUI instrumentation init.
@@ -215,7 +219,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
}
if (!mMetricsFinalized) {
end(REASON_END_SURFACE_DESTROYED);
finish(mJankInfos.size() - 1);
finish();
}
}
}, 50);
@@ -309,7 +313,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
// Waiting at most 10 seconds for all callbacks to finish.
mWaitForFinishTimedOut = () -> {
Log.e(TAG, "force finish cuj because of time out:" + mSession.getName());
finish(mJankInfos.size() - 1);
finish();
};
mHandler.postDelayed(mWaitForFinishTimedOut, TimeUnit.SECONDS.toMillis(10));
notifyCujEvent(ACTION_SESSION_END);
@@ -426,51 +430,45 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
}
}
/**
* Finds the first index in {@link #mJankInfos} which happened on or after {@link #mEndVsyncId},
* or -1 if the session hasn't ended yet.
*/
private int getIndexOnOrAfterEnd() {
if (mEndVsyncId == INVALID_ID || mMetricsFinalized) {
return -1;
private boolean hasReceivedCallbacksAfterEnd() {
if (mEndVsyncId == INVALID_ID) {
return false;
}
JankInfo last = mJankInfos.size() == 0 ? null : mJankInfos.valueAt(mJankInfos.size() - 1);
if (last == null) {
return -1;
return false;
}
if (last.frameVsyncId < mEndVsyncId) {
return -1;
return false;
}
int lastIndex = -1;
for (int i = mJankInfos.size() - 1; i >= 0; i--) {
JankInfo info = mJankInfos.valueAt(i);
if (info.frameVsyncId >= mEndVsyncId) {
if (isLastIndexCandidate(info)) {
lastIndex = i;
if (callbacksReceived(info)) {
return true;
}
} else {
break;
}
}
return lastIndex;
return false;
}
private void processJankInfos() {
int indexOnOrAfterEnd = getIndexOnOrAfterEnd();
if (indexOnOrAfterEnd == -1) {
if (mMetricsFinalized) {
return;
}
finish(indexOnOrAfterEnd);
if (!hasReceivedCallbacksAfterEnd()) {
return;
}
finish();
}
private boolean isLastIndexCandidate(JankInfo info) {
private boolean callbacksReceived(JankInfo info) {
return mSurfaceOnly
? info.surfaceControlCallbackFired
: info.hwuiCallbackFired && info.surfaceControlCallbackFired;
}
private void finish(int indexOnOrAfterEnd) {
private void finish() {
mHandler.removeCallbacks(mWaitForFinishTimedOut);
mWaitForFinishTimedOut = null;
mMetricsFinalized = true;
@@ -484,12 +482,15 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
int missedAppFramesCount = 0;
int missedSfFramesCount = 0;
for (int i = 0; i <= indexOnOrAfterEnd; i++) {
for (int i = 0; i < mJankInfos.size(); i++) {
JankInfo info = mJankInfos.valueAt(i);
final boolean isFirstDrawn = !mSurfaceOnly && info.isFirstFrame;
if (isFirstDrawn) {
continue;
}
if (info.frameVsyncId > mEndVsyncId) {
break;
}
if (info.surfaceControlCallbackFired) {
totalFramesCount++;
boolean missedFrame = false;
@@ -541,7 +542,7 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
triggerPerfetto();
}
if (mSession.logToStatsd()) {
FrameworkStatsLog.write(
mStatsLog.write(
FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED,
mSession.getStatsdInteractionType(),
totalFramesCount,
@@ -691,6 +692,13 @@ public class FrameTracker extends SurfaceControl.OnJankDataListener
}
}
public static class StatsLogWrapper {
public void write(int code,
int arg1, long arg2, long arg3, long arg4, long arg5, long arg6) {
FrameworkStatsLog.write(code, arg1, arg2, arg3, arg4, arg5, arg6);
}
}
/**
* A listener that notifies cuj events.
*/

3
core/java/com/android/internal/jank/InteractionJankMonitor.java
View File

@@ -385,7 +385,8 @@ public class InteractionJankMonitor {
synchronized (mLock) {
FrameTrackerListener eventsListener = (s, act) -> handleCujEvents(act, s);
return new FrameTracker(session, mWorker.getThreadHandler(),
threadedRenderer, viewRoot, surfaceControl, choreographer, mMetrics,
threadedRenderer, viewRoot, surfaceControl, choreographer,
mMetrics, new FrameTracker.StatsLogWrapper(),
mTraceThresholdMissedFrames, mTraceThresholdFrameTimeMillis,
eventsListener, config);
}

134
core/tests/coretests/src/com/android/internal/jank/FrameTrackerTest.java
View File

@@ -23,11 +23,14 @@ import static android.view.SurfaceControl.JankData.JANK_SURFACEFLINGER_DEADLINE_
import static com.android.internal.jank.FrameTracker.SurfaceControlWrapper;
import static com.android.internal.jank.FrameTracker.ViewRootWrapper;
import static com.android.internal.jank.InteractionJankMonitor.CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE;
import static com.android.internal.jank.InteractionJankMonitor.CUJ_TO_STATSD_INTERACTION_TYPE;
import static com.android.internal.jank.InteractionJankMonitor.CUJ_WALLPAPER_TRANSITION;
import static com.android.internal.util.FrameworkStatsLog.UI_INTERACTION_FRAME_INFO_REPORTED;
import static com.google.common.truth.Truth.assertThat;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.doNothing;
import static org.mockito.Mockito.doReturn;
import static org.mockito.Mockito.mock;
@@ -50,6 +53,7 @@ import androidx.test.rule.ActivityTestRule;
import com.android.internal.jank.FrameTracker.ChoreographerWrapper;
import com.android.internal.jank.FrameTracker.FrameMetricsWrapper;
import com.android.internal.jank.FrameTracker.StatsLogWrapper;
import com.android.internal.jank.FrameTracker.ThreadedRendererWrapper;
import com.android.internal.jank.InteractionJankMonitor.Configuration;
import com.android.internal.jank.InteractionJankMonitor.Session;
@@ -76,6 +80,7 @@ public class FrameTrackerTest {
private SurfaceControlWrapper mSurfaceControlWrapper;
private ViewRootWrapper mViewRootWrapper;
private ChoreographerWrapper mChoreographer;
private StatsLogWrapper mStatsLog;
private ArgumentCaptor<OnJankDataListener> mListenerCapture;
private SurfaceControl mSurfaceControl;
@@ -103,6 +108,7 @@ public class FrameTrackerTest {
mListenerCapture.capture());
mChoreographer = mock(ChoreographerWrapper.class);
mStatsLog = mock(StatsLogWrapper.class);
}
private FrameTracker spyFrameTracker(int cuj, String postfix, boolean surfaceOnly) {
@@ -111,9 +117,10 @@ public class FrameTrackerTest {
Configuration config = mock(Configuration.class);
when(config.isSurfaceOnly()).thenReturn(surfaceOnly);
when(config.getSurfaceControl()).thenReturn(mSurfaceControl);
when(config.shouldDeferMonitor()).thenReturn(true);
FrameTracker frameTracker = Mockito.spy(
new FrameTracker(session, handler, mRenderer, mViewRootWrapper,
mSurfaceControlWrapper, mChoreographer, mWrapper,
mSurfaceControlWrapper, mChoreographer, mWrapper, mStatsLog,
/* traceThresholdMissedFrames= */ 1,
/* traceThresholdFrameTimeMillis= */ -1,
/* FrameTrackerListener= */ null, config));
@@ -139,7 +146,7 @@ public class FrameTrackerTest {
sendFirstWindowFrame(tracker, 100, JANK_APP_DEADLINE_MISSED, 100L);
// send another frame with a short duration - should not be considered janky
sendFirstWindowFrame(tracker, 5, JANK_NONE, 101L);
sendFrame(tracker, 5, JANK_NONE, 101L);
// end the trace session, the last janky frame is after the end() so is discarded.
when(mChoreographer.getVsyncId()).thenReturn(102L);
@@ -149,6 +156,13 @@ public class FrameTrackerTest {
verify(tracker).removeObservers();
verify(tracker, never()).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(0L) /* missedFrames */,
eq(5000000L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
@Test
@@ -175,6 +189,14 @@ public class FrameTrackerTest {
// We detected a janky frame - trigger Perfetto
verify(tracker).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(1L) /* missedFrames */,
eq(40000000L) /* maxFrameTimeNanos */,
eq(1L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
@Test
@@ -201,6 +223,14 @@ public class FrameTrackerTest {
// We detected a janky frame - trigger Perfetto
verify(tracker, never()).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(0L) /* missedFrames */,
eq(4000000L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
@Test
@@ -227,6 +257,14 @@ public class FrameTrackerTest {
// We detected a janky frame - trigger Perfetto
verify(tracker).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(1L) /* missedFrames */,
eq(40000000L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(1L) /* missedAppFramesCount */);
}
@Test
@@ -256,6 +294,53 @@ public class FrameTrackerTest {
// We detected a janky frame - trigger Perfetto
verify(tracker).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(1L) /* missedFrames */,
eq(50000000L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(1L) /* missedAppFramesCount */);
}
/**
* b/223787365
*/
@Test
public void testNoOvercountingAfterEnd() {
FrameTracker tracker = spyFrameTracker(
CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE, CUJ_POSTFIX, /* surfaceOnly= */ false);
when(mChoreographer.getVsyncId()).thenReturn(100L);
tracker.begin();
verify(mRenderer, only()).addObserver(any());
// send first frame - not janky
sendFrame(tracker, 4, JANK_NONE, 100L);
// send another frame - not janky
sendFrame(tracker, 4, JANK_NONE, 101L);
// end the trace session, simulate one more valid callback came after the end call.
when(mChoreographer.getVsyncId()).thenReturn(102L);
tracker.end(FrameTracker.REASON_END_NORMAL);
// Send incomplete callback for 102L
sendSfFrame(102L, JANK_NONE);
// Send janky but complete callbck fo 103L
sendFrame(tracker, 50, JANK_APP_DEADLINE_MISSED, 103L);
verify(tracker).removeObservers();
verify(tracker, never()).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_NOTIFICATION_SHADE_EXPAND_COLLAPSE]),
eq(2L) /* totalFrames */,
eq(0L) /* missedFrames */,
eq(4000000L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
@Test
@@ -370,6 +455,14 @@ public class FrameTrackerTest {
verify(mSurfaceControlWrapper).removeJankStatsListener(any());
verify(tracker).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
eq(2L) /* totalFrames */,
eq(1L) /* missedFrames */,
eq(0L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(1L) /* missedAppFramesCount */);
}
@Test
@@ -396,6 +489,14 @@ public class FrameTrackerTest {
verify(mSurfaceControlWrapper).removeJankStatsListener(any());
verify(tracker, never()).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
eq(2L) /* totalFrames */,
eq(0L) /* missedFrames */,
eq(0L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
@Test
@@ -422,6 +523,14 @@ public class FrameTrackerTest {
verify(mSurfaceControlWrapper).removeJankStatsListener(any());
verify(tracker, never()).triggerPerfetto();
verify(mStatsLog).write(eq(UI_INTERACTION_FRAME_INFO_REPORTED),
eq(CUJ_TO_STATSD_INTERACTION_TYPE[CUJ_WALLPAPER_TRANSITION]),
eq(2L) /* totalFrames */,
eq(0L) /* missedFrames */,
eq(0L) /* maxFrameTimeNanos */,
eq(0L) /* missedSfFramesCount */,
eq(0L) /* missedAppFramesCount */);
}
private void sendFirstWindowFrame(FrameTracker tracker, long durationMillis,
@@ -445,13 +554,22 @@ public class FrameTrackerTest {
private void sendFrame(FrameTracker tracker, long durationMillis,
@JankType int jankType, long vsyncId, boolean firstWindowFrame) {
if (!tracker.mSurfaceOnly) {
when(mWrapper.getTiming()).thenReturn(new long[]{0, vsyncId});
doReturn(firstWindowFrame ? 1L : 0L).when(mWrapper)
.getMetric(FrameMetrics.FIRST_DRAW_FRAME);
doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis))
.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
tracker.onFrameMetricsAvailable(0);
sendHwuiFrame(tracker, durationMillis, vsyncId, firstWindowFrame);
}
sendSfFrame(vsyncId, jankType);
}
private void sendHwuiFrame(FrameTracker tracker, long durationMillis, long vsyncId,
boolean firstWindowFrame) {
when(mWrapper.getTiming()).thenReturn(new long[]{0, vsyncId});
doReturn(firstWindowFrame ? 1L : 0L).when(mWrapper)
.getMetric(FrameMetrics.FIRST_DRAW_FRAME);
doReturn(TimeUnit.MILLISECONDS.toNanos(durationMillis))
.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
tracker.onFrameMetricsAvailable(0);
}
private void sendSfFrame(long vsyncId, @JankType int jankType) {
mListenerCapture.getValue().onJankDataAvailable(new JankData[] {
new JankData(vsyncId, jankType)
});

4
core/tests/coretests/src/com/android/internal/jank/InteractionJankMonitorTest.java
View File

@@ -46,6 +46,7 @@ import androidx.test.rule.ActivityTestRule;
import com.android.internal.jank.FrameTracker.ChoreographerWrapper;
import com.android.internal.jank.FrameTracker.FrameMetricsWrapper;
import com.android.internal.jank.FrameTracker.StatsLogWrapper;
import com.android.internal.jank.FrameTracker.SurfaceControlWrapper;
import com.android.internal.jank.FrameTracker.ThreadedRendererWrapper;
import com.android.internal.jank.FrameTracker.ViewRootWrapper;
@@ -202,7 +203,8 @@ public class InteractionJankMonitorTest {
FrameTracker tracker = spy(new FrameTracker(session, mWorker.getThreadHandler(),
threadedRenderer, viewRoot, surfaceControl, choreographer,
new FrameMetricsWrapper(), /* traceThresholdMissedFrames= */ 1,
new FrameMetricsWrapper(), new StatsLogWrapper(),
/* traceThresholdMissedFrames= */ 1,
/* traceThresholdFrameTimeMillis= */ -1, listener, configuration));
doNothing().when(tracker).postTraceStartMarker();