Merge "Choreographer: add more traces" into sc-dev

core/java/android/view/Choreographer.java

@@ -693,12 +693,23 @@ public final class Choreographer {
         ThreadedRenderer.setFPSDivisor(divisor);
     }
 
+    private void traceMessage(String msg) {
+        Trace.traceBegin(Trace.TRACE_TAG_VIEW, msg);
+        Trace.traceEnd(Trace.TRACE_TAG_VIEW);
+    }
+
     void doFrame(long frameTimeNanos, int frame,
             DisplayEventReceiver.VsyncEventData vsyncEventData) {
         final long startNanos;
         final long frameIntervalNanos = vsyncEventData.frameInterval;
+        try {
+            if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
+                Trace.traceBegin(Trace.TRACE_TAG_VIEW,
+                        "Choreographer#doFrame " + vsyncEventData.id);
+            }
             synchronized (mLock) {
                 if (!mFrameScheduled) {
+                    traceMessage("Frame not scheduled");
                     return; // no work to do
                 }
 
@@ -733,6 +744,7 @@ public final class Choreographer {
                         Log.d(TAG, "Frame time appears to be going backwards.  May be due to a "
                                 + "previously skipped frame.  Waiting for next vsync.");
                     }
+                    traceMessage("Frame time goes backward");
                     scheduleVsyncLocked();
                     return;
                 }
@@ -740,6 +752,7 @@ public final class Choreographer {
                 if (mFPSDivisor > 1) {
                     long timeSinceVsync = frameTimeNanos - mLastFrameTimeNanos;
                     if (timeSinceVsync < (frameIntervalNanos * mFPSDivisor) && timeSinceVsync > 0) {
+                        traceMessage("Frame skipped due to FPSDivisor");
                         scheduleVsyncLocked();
                         return;
                     }
@@ -753,11 +766,6 @@ public final class Choreographer {
                 mLastVsyncEventData = vsyncEventData;
             }
 
-        try {
-            if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
-                Trace.traceBegin(Trace.TRACE_TAG_VIEW,
-                        "Choreographer#doFrame " + vsyncEventData.id);
-            }
             AnimationUtils.lockAnimationClock(frameTimeNanos / TimeUtils.NANOS_PER_MS);
 
             mFrameInfo.markInputHandlingStart();
@@ -870,7 +878,12 @@ public final class Choreographer {
 
     @UnsupportedAppUsage(maxTargetSdk = Build.VERSION_CODES.R, trackingBug = 170729553)
     private void scheduleVsyncLocked() {
+        try {
+            Trace.traceBegin(Trace.TRACE_TAG_VIEW, "Choreographer#scheduleVsyncLocked");
             mDisplayEventReceiver.scheduleVsync();
+        } finally {
+            Trace.traceEnd(Trace.TRACE_TAG_VIEW);
+        }
     }
 
     private boolean isRunningOnLooperThreadLocked() {
@@ -967,6 +980,11 @@ public final class Choreographer {
         @Override
         public void onVsync(long timestampNanos, long physicalDisplayId, int frame,
                 VsyncEventData vsyncEventData) {
+            try {
+                if (Trace.isTagEnabled(Trace.TRACE_TAG_VIEW)) {
+                    Trace.traceBegin(Trace.TRACE_TAG_VIEW,
+                            "Choreographer#onVsync " + vsyncEventData.id);
+                }
                 // Post the vsync event to the Handler.
                 // The idea is to prevent incoming vsync events from completely starving
                 // the message queue.  If there are no messages in the queue with timestamps
@@ -993,6 +1011,9 @@ public final class Choreographer {
                 Message msg = Message.obtain(mHandler, this);
                 msg.setAsynchronous(true);
                 mHandler.sendMessageAtTime(msg, timestampNanos / TimeUtils.NANOS_PER_MS);
+            } finally {
+                Trace.traceEnd(Trace.TRACE_TAG_VIEW);
+            }
         }
 
         @Override