Detect bad behavior earlier in Choreographer.

Detect wonky vsync timestamps (should they occur) and
warn loudly about them.

Warn when too many frames are skipped.  The threshold is pretty
conservative right now (only warn if at least 30 frames are skipped)
but it can be adjusted using system property.  Even skipping just a
couple of frames is enough to generate noticeable jank.
The threshold is currently intended to help track down bigger problems
such when an app does too much work on the UI thread.

Bug: 6574842
Change-Id: I4aac7e5e17d1fb51adb0510e318a72a28b3775ed

Author: Jeff Brown

core/java/android/view/Choreographer.java

@@ -103,6 +103,11 @@ protected Choreographer initialValue() {
     private static final boolean USE_FRAME_TIME = SystemProperties.getBoolean(
             "debug.choreographer.frametime", true);
 
+    // Set a limit to warn about skipped frames.
+    // Skipped frames imply jank.
+    private static final int SKIPPED_FRAME_WARNING_LIMIT = SystemProperties.getInt(
+            "debug.choreographer.skipwarning", 30);
+
     private static final long NANOS_PER_MS = 1000000;
 
     private static final int MSG_DO_FRAME = 0;
@@ -486,21 +491,26 @@ void doFrame(long frameTimeNanos, int frame) {
             startNanos = System.nanoTime();
             final long jitterNanos = startNanos - frameTimeNanos;
             if (jitterNanos >= mFrameIntervalNanos) {
+                final long skippedFrames = jitterNanos / mFrameIntervalNanos;
+                if (skippedFrames >= SKIPPED_FRAME_WARNING_LIMIT) {
+                    Log.w(TAG, "Skipped " + skippedFrames + " frames!  "
+                            + "The application may be doing too much work on its main thread.");
+                }
                 final long lastFrameOffset = jitterNanos % mFrameIntervalNanos;
                 if (DEBUG) {
                     Log.d(TAG, "Missed vsync by " + (jitterNanos * 0.000001f) + " ms "
                             + "which is more than the frame interval of "
                             + (mFrameIntervalNanos * 0.000001f) + " ms!  "
-                            + "Setting frame time to " + (lastFrameOffset * 0.000001f)
-                            + " ms in the past.");
+                            + "Skipping " + skippedFrames + " frames and setting frame "
+                            + "time to " + (lastFrameOffset * 0.000001f) + " ms in the past.");
                 }
                 frameTimeNanos = startNanos - lastFrameOffset;
             }
 
             if (frameTimeNanos < mLastFrameTimeNanos) {
                 if (DEBUG) {
                     Log.d(TAG, "Frame time appears to be going backwards.  May be due to a "
-                            + "previously skipped frame.  Waiting for next vsync");
+                            + "previously skipped frame.  Waiting for next vsync.");
                 }
                 scheduleVsyncLocked();
                 return;
@@ -658,6 +668,7 @@ public void handleMessage(Message msg) {
 
     private final class FrameDisplayEventReceiver extends DisplayEventReceiver
             implements Runnable {
+        private boolean mHavePendingVsync;
         private long mTimestampNanos;
         private int mFrame;
 
@@ -672,6 +683,21 @@ public void onVsync(long timestampNanos, int frame) {
             // the message queue.  If there are no messages in the queue with timestamps
             // earlier than the frame time, then the vsync event will be processed immediately.
             // Otherwise, messages that predate the vsync event will be handled first.
+            long now = System.nanoTime();
+            if (timestampNanos > now) {
+                Log.w(TAG, "Frame time is " + ((timestampNanos - now) * 0.000001f)
+                        + " ms in the future!  Check that graphics HAL is generating vsync "
+                        + "timestamps using the correct timebase.");
+                timestampNanos = now;
+            }
+
+            if (mHavePendingVsync) {
+                Log.w(TAG, "Already have a pending vsync event.  There should only be "
+                        + "one at a time.");
+            } else {
+                mHavePendingVsync = true;
+            }
+
             mTimestampNanos = timestampNanos;
             mFrame = frame;
             Message msg = Message.obtain(mHandler, this);
@@ -681,6 +707,7 @@ public void onVsync(long timestampNanos, int frame) {
 
         @Override
         public void run() {
+            mHavePendingVsync = false;
             doFrame(mTimestampNanos, mFrame);
         }
     }