Improve latency instrumentation. (95db2b20) · Commits · e / os / android_frameworks_base

core/java/android/view/HardwareRenderer.java

+41 −2

Original line number	Diff line number	Diff line
		@@ -837,10 +837,37 @@ public abstract class HardwareRenderer {
		(view.mPrivateFlags & View.INVALIDATED) == View.INVALIDATED;
		view.mPrivateFlags &= ~View.INVALIDATED;

		final long getDisplayListStartTime;
		if (ViewDebug.DEBUG_LATENCY) {
		getDisplayListStartTime = System.nanoTime();
		}

		DisplayList displayList = view.getDisplayList();

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "- getDisplayList() took "
		+ ((now - getDisplayListStartTime) * 0.000001f) + "ms");
		}

		if (displayList != null) {
		if (canvas.drawDisplayList(displayList, view.getWidth(),
		view.getHeight(), mRedrawClip)) {
		final long drawDisplayListStartTime;
		if (ViewDebug.DEBUG_LATENCY) {
		drawDisplayListStartTime = System.nanoTime();
		}

		boolean invalidateNeeded = canvas.drawDisplayList(
		displayList, view.getWidth(),
		view.getHeight(), mRedrawClip);

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "- drawDisplayList() took "
		+ ((now - drawDisplayListStartTime) * 0.000001f)
		+ "ms, invalidateNeeded=" + invalidateNeeded + ".");
		}

		if (invalidateNeeded) {
		if (mRedrawClip.isEmpty() \|\| view.getParent() == null) {
		view.invalidate();
		} else {
		@@ -872,7 +899,19 @@ public abstract class HardwareRenderer {

		attachInfo.mIgnoreDirtyState = false;

		final long eglSwapBuffersStartTime;
		if (ViewDebug.DEBUG_LATENCY) {
		eglSwapBuffersStartTime = System.nanoTime();
		}

		sEgl.eglSwapBuffers(sEglDisplay, mEglSurface);

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "- eglSwapBuffers() took "
		+ ((now - eglSwapBuffersStartTime) * 0.000001f) + "ms");
		}

		checkEglErrors();

		return dirty == null;

core/java/android/view/ViewDebug.java

+8 −5

Original line number	Diff line number	Diff line
		@@ -127,16 +127,19 @@ public class ViewDebug {
		* Logs the relative difference between the time an event was created and the time it
		* was delivered.
		*
		* Logs the time spent waiting for Surface.lockCanvas() or eglSwapBuffers().
		* This is time that the event loop spends blocked and unresponsive. Ideally, drawing
		* and animations should be perfectly synchronized with VSYNC so that swap buffers
		* is instantaneous.
		* Logs the time spent waiting for Surface.lockCanvas(), Surface.unlockCanvasAndPost()
		* or eglSwapBuffers(). This is time that the event loop spends blocked and unresponsive.
		* Ideally, drawing and animations should be perfectly synchronized with VSYNC so that
		* dequeuing and queueing buffers is instantaneous.
		*
		* Logs the time spent in ViewRoot.performTraversals() or ViewRoot.draw().
		* Logs the time spent in ViewRoot.performTraversals() and ViewRoot.performDraw().
		* @hide
		*/
		public static final boolean DEBUG_LATENCY = false;

		/** @hide */
		public static final String DEBUG_LATENCY_TAG = "ViewLatency";

		/**
		* <p>Enables or disables views consistency check. Even when this property is enabled,
		* view consistency checks happen only if {@link false} is set

core/java/android/view/ViewRootImpl.java

+36 −9

Original line number	Diff line number	Diff line
		@@ -2024,7 +2024,19 @@ public final class ViewRootImpl extends Handler implements ViewParent,
		canvas.setScreenDensity(scalingRequired
		? DisplayMetrics.DENSITY_DEVICE : 0);
		mAttachInfo.mSetIgnoreDirtyState = false;

		final long drawStartTime;
		if (ViewDebug.DEBUG_LATENCY) {
		drawStartTime = System.nanoTime();
		}

		mView.draw(canvas);

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "- draw() took "
		+ ((now - drawStartTime) * 0.000001f) + "ms");
		}
		} finally {
		if (!mAttachInfo.mSetIgnoreDirtyState) {
		// Only clear the flag if it was not set during the mView.draw() call
		@@ -2040,15 +2052,25 @@ public final class ViewRootImpl extends Handler implements ViewParent,
		EventLog.writeEvent(60000, SystemClock.elapsedRealtime() - startTime);
		}
		}

		} finally {
		surface.unlockCanvasAndPost(canvas);
		final long unlockCanvasAndPostStartTime;
		if (ViewDebug.DEBUG_LATENCY) {
		unlockCanvasAndPostStartTime = System.nanoTime();
		}

		surface.unlockCanvasAndPost(canvas);

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "- unlockCanvasAndPost() took "
		+ ((now - unlockCanvasAndPostStartTime) * 0.000001f) + "ms");
		}

		if (LOCAL_LOGV) {
		Log.v(TAG, "Surface " + surface + " unlockCanvasAndPost");
		}
		}
		}

		if (animating) {
		mFullRedrawNeeded = true;
		@@ -2437,17 +2459,22 @@ public final class ViewRootImpl extends Handler implements ViewParent,
		if (ViewDebug.DEBUG_LATENCY) {
		traversalStartTime = System.nanoTime();
		mLastDrawDurationNanos = 0;
		if (mLastTraversalFinishedTimeNanos != 0) {
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "Starting performTraversals(); it has been "
		+ ((traversalStartTime - mLastTraversalFinishedTimeNanos) * 0.000001f)
		+ "ms since the last traversals finished.");
		} else {
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "Starting performTraversals().");
		}
		}

		performTraversals();

		if (ViewDebug.DEBUG_LATENCY) {
		long now = System.nanoTime();
		Log.d(TAG, "Latency: Spent "
		Log.d(ViewDebug.DEBUG_LATENCY_TAG, "performTraversals() took "
		+ ((now - traversalStartTime) * 0.000001f)
		+ "ms in performTraversals(), with "
		+ (mLastDrawDurationNanos * 0.000001f)
		+ "ms of that time in draw()");
		+ "ms.");
		mLastTraversalFinishedTimeNanos = now;
		}