Infrastructure of Always-on tracing (ba492039) · Commits · e / os / android_frameworks_base

core/java/android/view/FrameMetrics.java

+5 −2

Original line number	Diff line number	Diff line
		@@ -250,8 +250,11 @@ public final class FrameMetrics {
		Index.INTENDED_VSYNC, Index.FRAME_COMPLETED,
		};

		/**
		* @hide
		*/
		@UnsupportedAppUsage
		/* package */ final long[] mTimingData;
		public final long[] mTimingData;

		/**
		* Constructs a FrameMetrics object as a copy.
		@@ -270,7 +273,7 @@ public final class FrameMetrics {
		/**
		* @hide
		*/
		FrameMetrics() {
		public FrameMetrics() {
		mTimingData = new long[Index.FRAME_STATS_COUNT];
		}

core/java/com/android/internal/jank/FrameTracker.java

0 → 100644

+234 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2020 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.
		*/

		package com.android.internal.jank;

		import android.annotation.NonNull;
		import android.graphics.HardwareRendererObserver;
		import android.os.Handler;
		import android.os.Trace;
		import android.util.Log;
		import android.view.FrameMetrics;
		import android.view.ThreadedRenderer;

		import com.android.internal.annotations.VisibleForTesting;
		import com.android.internal.jank.InteractionJankMonitor.Session;

		/**
		* @hide
		*/
		public class FrameTracker implements HardwareRendererObserver.OnFrameMetricsAvailableListener {
		private static final String TAG = FrameTracker.class.getSimpleName();
		private static final boolean DEBUG = false;
		//TODO (163431584): need also consider other refresh rates.
		private static final long CRITERIA = 1000000000 / 60;
		@VisibleForTesting
		public static final long UNKNOWN_TIMESTAMP = -1;

		@VisibleForTesting
		public long mBeginTime = UNKNOWN_TIMESTAMP;
		@VisibleForTesting
		public long mEndTime = UNKNOWN_TIMESTAMP;
		public boolean mShouldTriggerTrace;
		public HardwareRendererObserver mObserver;
		public ThreadedRendererWrapper mRendererWrapper;
		public FrameMetricsWrapper mMetricsWrapper;

		private Session mSession;

		public FrameTracker(@NonNull Session session,
		@NonNull Handler handler, @NonNull ThreadedRenderer renderer) {
		mSession = session;
		mRendererWrapper = new ThreadedRendererWrapper(renderer);
		mMetricsWrapper = new FrameMetricsWrapper();
		mObserver = new HardwareRendererObserver(this, mMetricsWrapper.getTiming(), handler);
		}

		/**
		* This constructor is only for unit tests.
		* @param session a trace session.
		* @param renderer a test double for ThreadedRenderer
		* @param metrics a test double for FrameMetrics
		*/
		@VisibleForTesting
		public FrameTracker(@NonNull Session session, Handler handler,
		@NonNull ThreadedRendererWrapper renderer, @NonNull FrameMetricsWrapper metrics) {
		mSession = session;
		mRendererWrapper = renderer;
		mMetricsWrapper = metrics;
		mObserver = new HardwareRendererObserver(this, mMetricsWrapper.getTiming(), handler);
		}

		/**
		* Begin a trace session of the CUJ.
		*/
		public void begin() {
		long timestamp = System.nanoTime();
		if (DEBUG) {
		Log.d(TAG, "begin: time(ns)=" + timestamp + ", begin(ns)=" + mBeginTime
		+ ", end(ns)=" + mEndTime + ", session=" + mSession);
		}
		if (mBeginTime != UNKNOWN_TIMESTAMP && mEndTime == UNKNOWN_TIMESTAMP) {
		// We have an ongoing tracing already, skip subsequent calls.
		return;
		}
		mBeginTime = timestamp;
		mEndTime = UNKNOWN_TIMESTAMP;
		Trace.beginAsyncSection(mSession.getName(), (int) mBeginTime);
		mRendererWrapper.addObserver(mObserver);
		}

		/**
		* End the trace session of the CUJ.
		*/
		public void end() {
		long timestamp = System.nanoTime();
		if (DEBUG) {
		Log.d(TAG, "end: time(ns)=" + timestamp + ", begin(ns)=" + mBeginTime
		+ ", end(ns)=" + mEndTime + ", session=" + mSession);
		}
		if (mBeginTime == UNKNOWN_TIMESTAMP \|\| mEndTime != UNKNOWN_TIMESTAMP) {
		// We haven't started a trace yet.
		return;
		}
		mEndTime = timestamp;
		Trace.endAsyncSection(mSession.getName(), (int) mBeginTime);
		}

		/**
		* Check if we had a janky frame according to the metrics.
		* @param metrics frame metrics
		* @return true if it is a janky frame
		*/
		@VisibleForTesting
		public boolean isJankyFrame(FrameMetricsWrapper metrics) {
		long totalDurationMs = metrics.getMetric(FrameMetrics.TOTAL_DURATION);
		boolean isFirstFrame = metrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME) == 1;
		boolean isJanky = !isFirstFrame && totalDurationMs - CRITERIA > 0;

		if (DEBUG) {
		StringBuilder sb = new StringBuilder();
		sb.append(isJanky).append(",");
		sb.append(metrics.getMetric(FrameMetrics.FIRST_DRAW_FRAME)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.INPUT_HANDLING_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.ANIMATION_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.LAYOUT_MEASURE_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.DRAW_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.SYNC_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.COMMAND_ISSUE_DURATION)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.SWAP_BUFFERS_DURATION)).append(",");
		sb.append(totalDurationMs).append(",");
		sb.append(metrics.getMetric(FrameMetrics.INTENDED_VSYNC_TIMESTAMP)).append(",");
		sb.append(metrics.getMetric(FrameMetrics.VSYNC_TIMESTAMP)).append(",");
		Log.v(TAG, "metrics=" + sb.toString());
		}

		return isJanky;
		}

		@Override
		public void onFrameMetricsAvailable(int dropCountSinceLastInvocation) {
		// Since this callback might come a little bit late after the end() call.
		// We should keep tracking the begin / end timestamp.
		// Then compare with vsync timestamp to check if the frame is in the duration of the CUJ.

		if (mBeginTime == UNKNOWN_TIMESTAMP) return; // We haven't started tracing yet.
		long vsyncTimestamp = mMetricsWrapper.getMetric(FrameMetrics.VSYNC_TIMESTAMP);
		if (vsyncTimestamp < mBeginTime) return; // The tracing has been started.

		// If the end time has not been set, we are still in the tracing.
		if (mEndTime != UNKNOWN_TIMESTAMP && vsyncTimestamp > mEndTime) {
		// The tracing has been ended, remove the observer, see if need to trigger perfetto.
		mRendererWrapper.removeObserver(mObserver);
		// Trigger perfetto if necessary.
		if (mShouldTriggerTrace) {
		if (DEBUG) {
		Log.v(TAG, "Found janky frame, triggering perfetto.");
		}
		triggerPerfetto();
		}
		return;
		}

		// The frame is in the duration of the CUJ, check if it catches the deadline.
		if (isJankyFrame(mMetricsWrapper)) {
		mShouldTriggerTrace = true;
		}
		}

		/**
		* Trigger the prefetto daemon.
		*/
		@VisibleForTesting
		public void triggerPerfetto() {
		InteractionJankMonitor.trigger();
		}

		/**
		* A wrapper class that we can spy FrameMetrics (a final class) in unit tests.
		*/
		public static class FrameMetricsWrapper {
		private FrameMetrics mFrameMetrics;

		public FrameMetricsWrapper() {
		mFrameMetrics = new FrameMetrics();
		}

		/**
		* Wrapper method.
		* @return timing data of the metrics
		*/
		public long[] getTiming() {
		return mFrameMetrics.mTimingData;
		}

		/**
		* Wrapper method.
		* @param index specific index of the timing data
		* @return the timing data of the specified index
		*/
		public long getMetric(int index) {
		return mFrameMetrics.getMetric(index);
		}
		}

		/**
		* A wrapper class that we can spy ThreadedRenderer (a final class) in unit tests.
		*/
		public static class ThreadedRendererWrapper {
		private ThreadedRenderer mRenderer;

		public ThreadedRendererWrapper(ThreadedRenderer renderer) {
		mRenderer = renderer;
		}

		/**
		* Wrapper method.
		* @param observer observer
		*/
		public void addObserver(HardwareRendererObserver observer) {
		mRenderer.addObserver(observer);
		}

		/**
		* Wrapper method.
		* @param observer observer
		*/
		public void removeObserver(HardwareRendererObserver observer) {
		mRenderer.removeObserver(observer);
		}
		}
		}

core/java/com/android/internal/jank/InteractionJankMonitor.java

0 → 100644

+181 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2020 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.
		*/

		package com.android.internal.jank;

		import android.annotation.IntDef;
		import android.annotation.NonNull;
		import android.os.HandlerThread;
		import android.view.ThreadedRenderer;
		import android.view.View;

		import com.android.internal.annotations.VisibleForTesting;

		import java.lang.annotation.Retention;
		import java.lang.annotation.RetentionPolicy;
		import java.util.HashMap;
		import java.util.Map;

		/**
		* This class let users to begin and end the always on tracing mechanism.
		* @hide
		*/
		public class InteractionJankMonitor {
		private static final String TAG = InteractionJankMonitor.class.getSimpleName();
		private static final boolean DEBUG = false;
		private static final Object LOCK = new Object();
		public static final int CUJ_NOTIFICATION_SHADE_MOTION = 0;
		public static final int CUJ_NOTIFICATION_SHADE_GESTURE = 1;

		private static ThreadedRenderer sRenderer;
		private static Map<String, FrameTracker> sRunningTracker;
		private static HandlerThread sWorker;
		private static boolean sInitialized;

		/** @hide */
		@IntDef({
		CUJ_NOTIFICATION_SHADE_MOTION,
		CUJ_NOTIFICATION_SHADE_GESTURE
		})
		@Retention(RetentionPolicy.SOURCE)
		public @interface CujType {}

		/**
		* @param view Any view in the view tree to get context and ThreadedRenderer.
		*/
		public static void init(@NonNull View view) {
		init(view, null, null, null);
		}

		/**
		* Should be only invoked internally or from unit tests.
		*/
		@VisibleForTesting
		public static void init(@NonNull View view, @NonNull ThreadedRenderer renderer,
		@NonNull Map<String, FrameTracker> map, @NonNull HandlerThread worker) {
		//TODO (163505250): This should be no-op if not in droid food rom.
		synchronized (LOCK) {
		if (!sInitialized) {
		if (!view.isAttachedToWindow()) {
		throw new IllegalStateException("View is not attached!");
		}
		sRenderer = renderer == null ? view.getThreadedRenderer() : renderer;
		sRunningTracker = map == null ? new HashMap<>() : map;
		sWorker = worker == null ? new HandlerThread("Aot-Worker") : worker;
		sWorker.start();
		sInitialized = true;
		}
		}
		}

		/**
		* Must invoke init() before invoking this method.
		*/
		public static void begin(@NonNull @CujType int cujType) {
		begin(cujType, null);
		}

		/**
		* Should be only invoked internally or from unit tests.
		*/
		@VisibleForTesting
		public static void begin(@NonNull @CujType int cujType, FrameTracker tracker) {
		//TODO (163505250): This should be no-op if not in droid food rom.
		//TODO (163510843): Remove synchronized, add @UiThread if only invoked from ui threads.
		synchronized (LOCK) {
		checkInitStateLocked();
		Session session = new Session(cujType);
		FrameTracker currentTracker = getTracker(session.getName());
		if (currentTracker != null) return;
		if (tracker == null) {
		tracker = new FrameTracker(session, sWorker.getThreadHandler(), sRenderer);
		}
		sRunningTracker.put(session.getName(), tracker);
		tracker.begin();
		}
		}

		/**
		* Must invoke init() before invoking this method.
		*/
		public static void end(@NonNull @CujType int cujType) {
		//TODO (163505250): This should be no-op if not in droid food rom.
		//TODO (163510843): Remove synchronized, add @UiThread if only invoked from ui threads.
		synchronized (LOCK) {
		checkInitStateLocked();
		Session session = new Session(cujType);
		FrameTracker tracker = getTracker(session.getName());
		if (tracker != null) {
		tracker.end();
		sRunningTracker.remove(session.getName());
		}
		}
		}

		private static void checkInitStateLocked() {
		if (!sInitialized) {
		throw new IllegalStateException("InteractionJankMonitor not initialized!");
		}
		}

		/**
		* Should be only invoked from unit tests.
		*/
		@VisibleForTesting
		public static void reset() {
		sInitialized = false;
		sRenderer = null;
		sRunningTracker = null;
		if (sWorker != null) {
		sWorker.quit();
		sWorker = null;
		}
		}

		private static FrameTracker getTracker(String sessionName) {
		synchronized (LOCK) {
		return sRunningTracker.get(sessionName);
		}
		}

		/**
		* Trigger the perfetto daemon to collect and upload data.
		*/
		public static void trigger() {
		sWorker.getThreadHandler().post(
		() -> PerfettoTrigger.trigger(PerfettoTrigger.TRIGGER_TYPE_JANK));
		}

		/**
		* A class to represent a session.
		*/
		public static class Session {
		private @CujType int mId;

		public Session(@CujType int session) {
		mId = session;
		}

		public int getId() {
		return mId;
		}

		public String getName() {
		return "CujType<" + mId + ">";
		}
		}

		}

core/java/com/android/internal/jank/PerfettoTrigger.java

0 → 100644

+115 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2020 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.
		*/

		//TODO (165884885): Make PerfettoTrigger more generic and move it to another package.
		package com.android.internal.jank;

		import android.annotation.IntDef;
		import android.annotation.NonNull;
		import android.util.Log;

		import java.io.BufferedReader;
		import java.io.IOException;
		import java.io.InputStreamReader;
		import java.lang.annotation.Retention;
		import java.lang.annotation.RetentionPolicy;

		/**
		* A trigger implementation with perfetto backend.
		* @hide
		*/
		public class PerfettoTrigger {
		private static final String TAG = PerfettoTrigger.class.getSimpleName();
		private static final boolean DEBUG = false;
		private static final String TRIGGER_COMMAND = "/system/bin/trigger_perfetto";
		private static final String[] TRIGGER_TYPE_NAMES = new String[] { "jank-tracker" };
		public static final int TRIGGER_TYPE_JANK = 0;

		/** @hide */
		@IntDef({
		TRIGGER_TYPE_JANK
		})
		@Retention(RetentionPolicy.SOURCE)
		public @interface TriggerType {}

		/**
		* @param type the trigger type
		*/
		public static void trigger(@NonNull @TriggerType int type) {
		try {
		Token token = new Token(type, TRIGGER_TYPE_NAMES[type]);
		ProcessBuilder pb = new ProcessBuilder(TRIGGER_COMMAND, token.getName());
		if (DEBUG) {
		StringBuilder sb = new StringBuilder();
		for (String arg : pb.command()) {
		sb.append(arg).append(" ");
		}
		Log.d(TAG, "Triggering " + sb.toString());
		}
		Process process = pb.start();
		if (DEBUG) {
		readConsoleOutput(process);
		}
		} catch (IOException \| InterruptedException e) {
		Log.w(TAG, "Failed to trigger " + type, e);
		}
		}

		private static void readConsoleOutput(@NonNull Process process)
		throws IOException, InterruptedException {
		process.waitFor();
		try (BufferedReader errReader =
		new BufferedReader(new InputStreamReader(process.getErrorStream()))) {
		StringBuilder errLine = new StringBuilder();
		String line;
		while ((line = errReader.readLine()) != null) {
		errLine.append(line).append("\n");
		}
		errLine.append(", code=").append(process.exitValue());
		Log.d(TAG, "err message=" + errLine.toString());
		}
		}

		/**
		* Token which is used to trigger perfetto.
		*/
		public static class Token {
		private int mType;
		private String mName;

		Token(@TriggerType int type, String name) {
		mType = type;
		mName = name;
		}

		/**
		* Get trigger type.
		* @return trigger type, should be @TriggerType
		*/
		public int getType() {
		return mType;
		}

		/**
		* Get name of this token as the argument while triggering perfetto.
		* @return name
		*/
		public String getName() {
		return mName;
		}
		}

		}

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

0 → 100644

+130 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2020 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.
		*/

		package com.android.internal.jank;

		import static com.android.internal.jank.InteractionJankMonitor.CUJ_NOTIFICATION_SHADE_GESTURE;

		import static com.google.common.truth.Truth.assertThat;

		import static org.mockito.ArgumentMatchers.any;
		import static org.mockito.Mockito.doNothing;
		import static org.mockito.Mockito.doReturn;
		import static org.mockito.Mockito.only;
		import static org.mockito.Mockito.verify;

		import android.os.Handler;
		import android.view.FrameMetrics;
		import android.view.View;
		import android.view.ViewAttachTestActivity;

		import androidx.test.filters.SmallTest;
		import androidx.test.rule.ActivityTestRule;

		import com.android.internal.jank.FrameTracker.FrameMetricsWrapper;
		import com.android.internal.jank.FrameTracker.ThreadedRendererWrapper;
		import com.android.internal.jank.InteractionJankMonitor.Session;

		import org.junit.Before;
		import org.junit.Rule;
		import org.junit.Test;
		import org.mockito.Mockito;

		import java.util.concurrent.TimeUnit;

		@SmallTest
		public class FrameTrackerTest {
		private ViewAttachTestActivity mActivity;

		@Rule
		public ActivityTestRule<ViewAttachTestActivity> mRule =
		new ActivityTestRule<>(ViewAttachTestActivity.class);

		private FrameTracker mTracker;
		private ThreadedRendererWrapper mRenderer;
		private FrameMetricsWrapper mWrapper;

		@Before
		public void setup() {
		// Prepare an activity for getting ThreadedRenderer later.
		mActivity = mRule.getActivity();
		View view = mActivity.getWindow().getDecorView();
		assertThat(view.isAttachedToWindow()).isTrue();

		Handler handler = mRule.getActivity().getMainThreadHandler();
		mWrapper = Mockito.spy(new FrameMetricsWrapper());
		mRenderer = Mockito.spy(new ThreadedRendererWrapper(view.getThreadedRenderer()));
		doNothing().when(mRenderer).addObserver(any());
		doNothing().when(mRenderer).removeObserver(any());

		Session session = new Session(CUJ_NOTIFICATION_SHADE_GESTURE);
		mTracker = Mockito.spy(new FrameTracker(session, handler, mRenderer, mWrapper));
		doNothing().when(mTracker).triggerPerfetto();
		}

		@Test
		public void testIsJankyFrame() {
		// We skip the first frame.
		doReturn(1L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME);
		doReturn(TimeUnit.MILLISECONDS.toNanos(20L))
		.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
		assertThat(mTracker.isJankyFrame(mWrapper)).isFalse();

		// Should exceed the criteria.
		doReturn(0L).when(mWrapper).getMetric(FrameMetrics.FIRST_DRAW_FRAME);
		doReturn(TimeUnit.MILLISECONDS.toNanos(20L))
		.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
		assertThat(mTracker.isJankyFrame(mWrapper)).isTrue();

		// Should be safe.
		doReturn(TimeUnit.MILLISECONDS.toNanos(10L))
		.when(mWrapper).getMetric(FrameMetrics.TOTAL_DURATION);
		assertThat(mTracker.isJankyFrame(mWrapper)).isFalse();
		}

		@Test
		public void testBeginEnd() {
		// assert the initial values
		assertThat(mTracker.mBeginTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);

		// Observer should be only added once in continuous calls.
		mTracker.begin();
		mTracker.begin();
		verify(mRenderer, only()).addObserver(any());

		// assert the values after begin call.
		assertThat(mTracker.mBeginTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		assertThat(mTracker.mEndTime).isEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);

		// simulate the callback during trace session
		// assert the isJankyFrame should be invoked as well.
		doReturn(System.nanoTime()).when(mWrapper).getMetric(FrameMetrics.VSYNC_TIMESTAMP);
		doReturn(true).when(mTracker).isJankyFrame(any());
		mTracker.onFrameMetricsAvailable(0);
		verify(mTracker).isJankyFrame(any());

		// end the trace session, simulate a callback came after the end call.
		// assert the end time should be set, the observer should be removed.
		// triggerPerfetto should be invoked as well.
		mTracker.end();
		doReturn(System.nanoTime()).when(mWrapper).getMetric(FrameMetrics.VSYNC_TIMESTAMP);
		assertThat(mTracker.mEndTime).isNotEqualTo(FrameTracker.UNKNOWN_TIMESTAMP);
		mTracker.onFrameMetricsAvailable(0);
		verify(mRenderer).removeObserver(any());
		verify(mTracker).triggerPerfetto();
		}
		}