Coalesce input events that arrive faster than 333Hz.

Some drivers report individual finger updates one at a time
instead of all at once.  When 10 fingers are down, this can
cause the framework to have to handle 10 times as many events
each with 10 times as much data.  Applications like
PointerLocation would get significantly bogged down by all
of the redundant samples.

This change coalesces samples that are closely spaced in time,
before they are dispatched, as part of the motion event batching
protocol.

Increased the size of the InputChannel shared memory buffer so
that applications can catch up faster if they accumulate a
backlog of samples.

Added logging code to help measure input dispatch and drawing
latency issues in the view hierarchy.  See ViewDebug.DEBUG_LATENCY.

Change-Id: Ia5898f781f19901d2225c529a910c32bdf4f504f

5 files changed, 167 insertions, 11 deletions

diff --git a/core/java/android/view/HardwareRenderer.java b/core/java/android/view/HardwareRenderer.java
index 28541fe..66f37f2 100644
--- a/core/java/android/view/HardwareRenderer.java
+++ b/core/java/android/view/HardwareRenderer.java
@@ -645,8 +645,21 @@ public abstract class HardwareRenderer {
                     }
     
                     attachInfo.mIgnoreDirtyState = false;
-    
+
+                    final long swapBuffersStartTime;
+                    if (ViewDebug.DEBUG_LATENCY) {
+                        swapBuffersStartTime = System.nanoTime();
+                    }
+
                     sEgl.eglSwapBuffers(sEglDisplay, mEglSurface);
+
+                    if (ViewDebug.DEBUG_LATENCY) {
+                        long now = System.nanoTime();
+                        Log.d(LOG_TAG, "Latency: Spent "
+                                + ((now - swapBuffersStartTime) * 0.000001f)
+                                + "ms waiting for eglSwapBuffers()");
+                    }
+
                     checkEglErrors();
                 }
             }
diff --git a/core/java/android/view/InputEvent.java b/core/java/android/view/InputEvent.java
index 87e7ea7..01ddcc9 100755
--- a/core/java/android/view/InputEvent.java
+++ b/core/java/android/view/InputEvent.java
@@ -106,6 +106,13 @@ public abstract class InputEvent implements Parcelable {
      */
     public abstract void setTainted(boolean tainted);
 
+    /**
+     * Returns the time (in ns) when this specific event was generated.
+     * The value is in nanosecond precision but it may not have nanosecond accuracy.
+     * @hide
+     */
+    public abstract long getEventTimeNano();
+
     public int describeContents() {
         return 0;
     }
diff --git a/core/java/android/view/KeyEvent.java b/core/java/android/view/KeyEvent.java
index c282e4b..13d8809 100755
--- a/core/java/android/view/KeyEvent.java
+++ b/core/java/android/view/KeyEvent.java
@@ -2340,6 +2340,12 @@ public class KeyEvent extends InputEvent implements Parcelable {
         return mEventTime;
     }
 
+    /** @hide */
+    @Override
+    public final long getEventTimeNano() {
+        return mEventTime * 1000000L;
+    }
+
     /**
      * Renamed to {@link #getDeviceId}.
      * 
diff --git a/core/java/android/view/ViewDebug.java b/core/java/android/view/ViewDebug.java
index c19a107..89736d6 100644
--- a/core/java/android/view/ViewDebug.java
+++ b/core/java/android/view/ViewDebug.java
@@ -141,6 +141,22 @@ public class ViewDebug {
     public static final boolean DEBUG_DRAG = false;
 
     /**
+     * Enables logging of factors that affect the latency and responsiveness of an application.
+     *
+     * 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 in ViewRoot.performTraversals() or ViewRoot.draw().
+     * @hide
+     */
+    public static final boolean DEBUG_LATENCY = false;
+
+    /**
      * <p>Enables or disables views consistency check. Even when this property is enabled,
      * view consistency checks happen only if {@link android.util.Config#DEBUG} is set
      * to true. The value of this property can be configured externally in one of the
diff --git a/core/java/android/view/ViewRoot.java b/core/java/android/view/ViewRoot.java
index 2f9d501..a899b46 100644
--- a/core/java/android/view/ViewRoot.java
+++ b/core/java/android/view/ViewRoot.java
@@ -186,6 +186,8 @@ public final class ViewRoot extends Handler implements ViewParent,
     final Rect mVisRect; // used to retrieve visible rect of focused view.
 
     boolean mTraversalScheduled;
+    long mLastTraversalFinishedTimeNanos;
+    long mLastDrawDurationNanos;
     boolean mWillDrawSoon;
     boolean mLayoutRequested;
     boolean mFirst;
@@ -671,6 +673,14 @@ public final class ViewRoot extends Handler implements ViewParent,
     public void scheduleTraversals() {
         if (!mTraversalScheduled) {
             mTraversalScheduled = true;
+
+            if (ViewDebug.DEBUG_LATENCY && mLastTraversalFinishedTimeNanos != 0) {
+                final long now = System.nanoTime();
+                Log.d(TAG, "Latency: Scheduled traversal, it has been "
+                        + ((now - mLastTraversalFinishedTimeNanos) * 0.000001f)
+                        + "ms since the last traversal finished.");
+            }
+
             sendEmptyMessage(DO_TRAVERSAL);
         }
     }
@@ -1389,8 +1399,18 @@ public final class ViewRoot extends Handler implements ViewParent,
 
         if (!cancelDraw && !newSurface) {
             mFullRedrawNeeded = false;
+
+            final long drawStartTime;
+            if (ViewDebug.DEBUG_LATENCY) {
+                drawStartTime = System.nanoTime();
+            }
+
             draw(fullRedrawNeeded);
 
+            if (ViewDebug.DEBUG_LATENCY) {
+                mLastDrawDurationNanos = System.nanoTime() - drawStartTime;
+            }
+
             if ((relayoutResult&WindowManagerImpl.RELAYOUT_FIRST_TIME) != 0
                     || mReportNextDraw) {
                 if (LOCAL_LOGV) {
@@ -1601,8 +1621,20 @@ public final class ViewRoot extends Handler implements ViewParent,
                 int right = dirty.right;
                 int bottom = dirty.bottom;
 
+                final long lockCanvasStartTime;
+                if (ViewDebug.DEBUG_LATENCY) {
+                    lockCanvasStartTime = System.nanoTime();
+                }
+
                 canvas = surface.lockCanvas(dirty);
 
+                if (ViewDebug.DEBUG_LATENCY) {
+                    long now = System.nanoTime();
+                    Log.d(TAG, "Latency: Spent "
+                            + ((now - lockCanvasStartTime) * 0.000001f)
+                            + "ms waiting for surface.lockCanvas()");
+                }
+
                 if (left != dirty.left || top != dirty.top || right != dirty.right ||
                         bottom != dirty.bottom) {
                     mAttachInfo.mIgnoreDirtyState = true;
@@ -2011,8 +2043,24 @@ public final class ViewRoot extends Handler implements ViewParent,
                 Debug.startMethodTracing("ViewRoot");
             }
 
+            final long traversalStartTime;
+            if (ViewDebug.DEBUG_LATENCY) {
+                traversalStartTime = System.nanoTime();
+                mLastDrawDurationNanos = 0;
+            }
+
             performTraversals();
 
+            if (ViewDebug.DEBUG_LATENCY) {
+                long now = System.nanoTime();
+                Log.d(TAG, "Latency: Spent "
+                        + ((now - traversalStartTime) * 0.000001f)
+                        + "ms in performTraversals(), with "
+                        + (mLastDrawDurationNanos * 0.000001f)
+                        + "ms of that time in draw()");
+                mLastTraversalFinishedTimeNanos = now;
+            }
+
             if (mProfile) {
                 Debug.stopMethodTracing();
                 mProfile = false;
@@ -2180,25 +2228,68 @@ public final class ViewRoot extends Handler implements ViewParent,
         }
     }
     
-    private void startInputEvent(InputQueue.FinishedCallback finishedCallback) {
+    private void startInputEvent(InputEvent event, InputQueue.FinishedCallback finishedCallback) {
         if (mFinishedCallback != null) {
             Slog.w(TAG, "Received a new input event from the input queue but there is "
                     + "already an unfinished input event in progress.");
         }
 
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventReceiveTimeNanos = System.nanoTime();
+            mInputEventDeliverTimeNanos = 0;
+            mInputEventDeliverPostImeTimeNanos = 0;
+        }
+
         mFinishedCallback = finishedCallback;
     }
 
-    private void finishInputEvent(boolean handled) {
+    private void finishInputEvent(InputEvent event, boolean handled) {
         if (LOCAL_LOGV) Log.v(TAG, "Telling window manager input event is finished");
 
-        if (mFinishedCallback != null) {
-            mFinishedCallback.finished(handled);
-            mFinishedCallback = null;
-        } else {
+        if (mFinishedCallback == null) {
             Slog.w(TAG, "Attempted to tell the input queue that the current input event "
                     + "is finished but there is no input event actually in progress.");
+            return;
+        }
+
+        if (ViewDebug.DEBUG_LATENCY) {
+            final long now = System.nanoTime();
+            final long eventTime = event.getEventTimeNano();
+            final StringBuilder msg = new StringBuilder();
+            msg.append("Latency: Spent ");
+            msg.append((now - mInputEventReceiveTimeNanos) * 0.000001f);
+            msg.append("ms processing ");
+            if (event instanceof KeyEvent) {
+                final KeyEvent  keyEvent = (KeyEvent)event;
+                msg.append("key event, action=");
+                msg.append(KeyEvent.actionToString(keyEvent.getAction()));
+            } else {
+                final MotionEvent motionEvent = (MotionEvent)event;
+                msg.append("motion event, action=");
+                msg.append(MotionEvent.actionToString(motionEvent.getAction()));
+                msg.append(", historySize=");
+                msg.append(motionEvent.getHistorySize());
+            }
+            msg.append(", handled=");
+            msg.append(handled);
+            msg.append(", received at +");
+            msg.append((mInputEventReceiveTimeNanos - eventTime) * 0.000001f);
+            if (mInputEventDeliverTimeNanos != 0) {
+                msg.append("ms, delivered at +");
+                msg.append((mInputEventDeliverTimeNanos - eventTime) * 0.000001f);
+            }
+            if (mInputEventDeliverPostImeTimeNanos != 0) {
+                msg.append("ms, delivered post IME at +");
+                msg.append((mInputEventDeliverPostImeTimeNanos - eventTime) * 0.000001f);
+            }
+            msg.append("ms, finished at +");
+            msg.append((now - eventTime) * 0.000001f);
+            msg.append("ms.");
+            Log.d(TAG, msg.toString());
         }
+
+        mFinishedCallback.finished(handled);
+        mFinishedCallback = null;
     }
     
     /**
@@ -2323,6 +2414,10 @@ public final class ViewRoot extends Handler implements ViewParent,
     }
 
     private void deliverPointerEvent(MotionEvent event, boolean sendDone) {
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventDeliverTimeNanos = System.nanoTime();
+        }
+
         if (mInputEventConsistencyVerifier != null) {
             if (event.isTouchEvent()) {
                 mInputEventConsistencyVerifier.onTouchEvent(event, 0);
@@ -2425,7 +2520,7 @@ public final class ViewRoot extends Handler implements ViewParent,
     private void finishMotionEvent(MotionEvent event, boolean sendDone, boolean handled) {
         event.recycle();
         if (sendDone) {
-            finishInputEvent(handled);
+            finishInputEvent(event, handled);
         }
         if (LOCAL_LOGV || WATCH_POINTER) {
             if ((event.getSource() & InputDevice.SOURCE_CLASS_POINTER) != 0) {
@@ -2435,6 +2530,10 @@ public final class ViewRoot extends Handler implements ViewParent,
     }
 
     private void deliverTrackballEvent(MotionEvent event, boolean sendDone) {
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventDeliverTimeNanos = System.nanoTime();
+        }
+
         if (DEBUG_TRACKBALL) Log.v(TAG, "Motion event:" + event);
 
         if (mInputEventConsistencyVerifier != null) {
@@ -2569,6 +2668,10 @@ public final class ViewRoot extends Handler implements ViewParent,
     }
 
     private void deliverGenericMotionEvent(MotionEvent event, boolean sendDone) {
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventDeliverTimeNanos = System.nanoTime();
+        }
+
         if (mInputEventConsistencyVerifier != null) {
             mInputEventConsistencyVerifier.onGenericMotionEvent(event, 0);
         }
@@ -2808,6 +2911,10 @@ public final class ViewRoot extends Handler implements ViewParent,
     }
 
     private void deliverKeyEvent(KeyEvent event, boolean sendDone) {
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventDeliverTimeNanos = System.nanoTime();
+        }
+
         if (mInputEventConsistencyVerifier != null) {
             mInputEventConsistencyVerifier.onKeyEvent(event, 0);
         }
@@ -2858,6 +2965,10 @@ public final class ViewRoot extends Handler implements ViewParent,
     }
 
     private void deliverKeyEventPostIme(KeyEvent event, boolean sendDone) {
+        if (ViewDebug.DEBUG_LATENCY) {
+            mInputEventDeliverPostImeTimeNanos = System.nanoTime();
+        }
+
         // If the view went away, then the event will not be handled.
         if (mView == null || !mAdded) {
             finishKeyEvent(event, sendDone, false);
@@ -2971,7 +3082,7 @@ public final class ViewRoot extends Handler implements ViewParent,
 
     private void finishKeyEvent(KeyEvent event, boolean sendDone, boolean handled) {
         if (sendDone) {
-            finishInputEvent(handled);
+            finishInputEvent(event, handled);
         }
     }
 
@@ -3262,16 +3373,19 @@ public final class ViewRoot extends Handler implements ViewParent,
         sendMessage(msg);
     }
     
+    private long mInputEventReceiveTimeNanos;
+    private long mInputEventDeliverTimeNanos;
+    private long mInputEventDeliverPostImeTimeNanos;
     private InputQueue.FinishedCallback mFinishedCallback;
     
     private final InputHandler mInputHandler = new InputHandler() {
         public void handleKey(KeyEvent event, InputQueue.FinishedCallback finishedCallback) {
-            startInputEvent(finishedCallback);
+            startInputEvent(event, finishedCallback);
             dispatchKey(event, true);
         }
 
         public void handleMotion(MotionEvent event, InputQueue.FinishedCallback finishedCallback) {
-            startInputEvent(finishedCallback);
+            startInputEvent(event, finishedCallback);
             dispatchMotion(event, true);
         }
     };