Added LatencyTimer to ease latency measurements

	new file:   core/java/android/os/LatencyTimer.java
	modified:   core/java/android/view/MotionEvent.java
	modified:   core/java/android/view/ViewRoot.java
	modified:   services/java/com/android/server/InputDevice.java
	modified:   services/java/com/android/server/KeyInputQueue.java
	modified:   services/java/com/android/server/WindowManagerService.java

3 files changed, 76 insertions, 25 deletions

diff --git a/services/java/com/android/server/InputDevice.java b/services/java/com/android/server/InputDevice.java
index 7b8a2a4..9c1f942 100644
--- a/services/java/com/android/server/InputDevice.java
+++ b/services/java/com/android/server/InputDevice.java
@@ -63,7 +63,7 @@ public class InputDevice {
             yMoveScale = my != 0 ? (1.0f/my) : 1.0f;
         }
         
-        MotionEvent generateMotion(InputDevice device, long curTime,
+        MotionEvent generateMotion(InputDevice device, long curTime, long curTimeNano,
                 boolean isAbs, Display display, int orientation,
                 int metaState) {
             if (!changed) {
@@ -167,7 +167,7 @@ public class InputDevice {
                 if (!isAbs) {
                     x = y = 0;
                 }
-                return MotionEvent.obtain(downTime, curTime, action,
+                return MotionEvent.obtainNano(downTime, curTime, curTimeNano, action,
                         scaledX, scaledY, scaledPressure, scaledSize, metaState,
                         xPrecision, yPrecision, device.id, edgeFlags);
             } else {
@@ -181,7 +181,7 @@ public class InputDevice {
                     }
                     return null;
                 }
-                MotionEvent me = MotionEvent.obtain(downTime, curTime,
+                MotionEvent me = MotionEvent.obtainNano(downTime, curTime, curTimeNano,
                         MotionEvent.ACTION_MOVE, scaledX, scaledY,
                         scaledPressure, scaledSize, metaState,
                         xPrecision, yPrecision, device.id, edgeFlags);
diff --git a/services/java/com/android/server/KeyInputQueue.java b/services/java/com/android/server/KeyInputQueue.java
index 411cd6b..78cdf8b 100644
--- a/services/java/com/android/server/KeyInputQueue.java
+++ b/services/java/com/android/server/KeyInputQueue.java
@@ -18,8 +18,9 @@ package com.android.server;
 
 import android.content.Context;
 import android.content.res.Configuration;
-import android.os.SystemClock;
+import android.os.LatencyTimer;
 import android.os.PowerManager;
+import android.os.SystemClock;
 import android.util.Log;
 import android.util.SparseArray;
 import android.view.Display;
@@ -73,14 +74,17 @@ public abstract class KeyInputQueue {
     public static final int FILTER_REMOVE = 0;
     public static final int FILTER_KEEP = 1;
     public static final int FILTER_ABORT = -1;
-    
+
+    private static final boolean MEASURE_LATENCY = false;
+    private LatencyTimer lt;
+
     public interface FilterCallback {
         int filterEvent(QueuedEvent ev);
     }
     
     static class QueuedEvent {
         InputDevice inputDevice;
-        long when;
+        long whenNano;
         int flags; // From the raw event
         int classType; // One of the class constants in InputEvent
         Object event;
@@ -88,7 +92,7 @@ public abstract class KeyInputQueue {
 
         void copyFrom(QueuedEvent that) {
             this.inputDevice = that.inputDevice;
-            this.when = that.when;
+            this.whenNano = that.whenNano;
             this.flags = that.flags;
             this.classType = that.classType;
             this.event = that.event;
@@ -107,6 +111,10 @@ public abstract class KeyInputQueue {
     }
 
     KeyInputQueue(Context context) {
+        if (MEASURE_LATENCY) {
+            lt = new LatencyTimer(100, 1000);
+        }
+
         PowerManager pm = (PowerManager)context.getSystemService(
                                                         Context.POWER_SERVICE);
         mWakeLock = pm.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK,
@@ -241,7 +249,7 @@ public abstract class KeyInputQueue {
                     
                     if (configChanged) {
                         synchronized (mFirst) {
-                            addLocked(di, SystemClock.uptimeMillis(), 0,
+                            addLocked(di, System.nanoTime(), 0,
                                     RawInputEvent.CLASS_CONFIGURATION_CHANGED,
                                     null);
                         }
@@ -256,6 +264,7 @@ public abstract class KeyInputQueue {
                         // timebase as SystemClock.uptimeMillis().
                         //curTime = gotOne ? ev.when : SystemClock.uptimeMillis();
                         final long curTime = SystemClock.uptimeMillis();
+                        final long curTimeNano = System.nanoTime();
                         //Log.i(TAG, "curTime=" + curTime + ", systemClock=" + SystemClock.uptimeMillis());
                         
                         final int classes = di.classes;
@@ -276,7 +285,7 @@ public abstract class KeyInputQueue {
                                 down = false;
                             }
                             int keycode = rotateKeyCodeLocked(ev.keycode);
-                            addLocked(di, curTime, ev.flags,
+                            addLocked(di, curTimeNano, ev.flags,
                                     RawInputEvent.CLASS_KEYBOARD,
                                     newKeyEvent(di, di.mDownTime, curTime, down,
                                             keycode, 0, scancode,
@@ -330,7 +339,7 @@ public abstract class KeyInputQueue {
                                 }
                                 
                                 MotionEvent me;
-                                me = di.mAbs.generateMotion(di, curTime, true,
+                                me = di.mAbs.generateMotion(di, curTime, curTimeNano, true,
                                         mDisplay, mOrientation, mGlobalMetaState);
                                 if (false) Log.v(TAG, "Absolute: x=" + di.mAbs.x
                                         + " y=" + di.mAbs.y + " ev=" + me);
@@ -338,15 +347,15 @@ public abstract class KeyInputQueue {
                                     if (WindowManagerPolicy.WATCH_POINTER) {
                                         Log.i(TAG, "Enqueueing: " + me);
                                     }
-                                    addLocked(di, curTime, ev.flags,
+                                    addLocked(di, curTimeNano, ev.flags,
                                             RawInputEvent.CLASS_TOUCHSCREEN, me);
                                 }
-                                me = di.mRel.generateMotion(di, curTime, false,
+                                me = di.mRel.generateMotion(di, curTime, curTimeNano, false,
                                         mDisplay, mOrientation, mGlobalMetaState);
                                 if (false) Log.v(TAG, "Relative: x=" + di.mRel.x
                                         + " y=" + di.mRel.y + " ev=" + me);
                                 if (me != null) {
-                                    addLocked(di, curTime, ev.flags,
+                                    addLocked(di, curTimeNano, ev.flags,
                                             RawInputEvent.CLASS_TRACKBALL, me);
                                 }
                             }
@@ -530,7 +539,7 @@ public abstract class KeyInputQueue {
         }
     }
     
-    private QueuedEvent obtainLocked(InputDevice device, long when,
+    private QueuedEvent obtainLocked(InputDevice device, long whenNano,
             int flags, int classType, Object event) {
         QueuedEvent ev;
         if (mCacheCount == 0) {
@@ -542,7 +551,7 @@ public abstract class KeyInputQueue {
             mCacheCount--;
         }
         ev.inputDevice = device;
-        ev.when = when;
+        ev.whenNano = whenNano;
         ev.flags = flags;
         ev.classType = classType;
         ev.event = event;
@@ -561,13 +570,13 @@ public abstract class KeyInputQueue {
         }
     }
 
-    private void addLocked(InputDevice device, long when, int flags,
+    private void addLocked(InputDevice device, long whenNano, int flags,
             int classType, Object event) {
         boolean poke = mFirst.next == mLast;
 
-        QueuedEvent ev = obtainLocked(device, when, flags, classType, event);
+        QueuedEvent ev = obtainLocked(device, whenNano, flags, classType, event);
         QueuedEvent p = mLast.prev;
-        while (p != mFirst && ev.when < p.when) {
+        while (p != mFirst && ev.whenNano < p.whenNano) {
             p = p.prev;
         }
 
@@ -578,8 +587,15 @@ public abstract class KeyInputQueue {
         ev.inQueue = true;
 
         if (poke) {
+            long time;
+            if (MEASURE_LATENCY) {
+                time = System.nanoTime();
+            }
             mFirst.notify();
             mWakeLock.acquire();
+            if (MEASURE_LATENCY) {
+                lt.sample("1 addLocked-queued event ", System.nanoTime() - time);
+            }
         }
     }
 
diff --git a/services/java/com/android/server/WindowManagerService.java b/services/java/com/android/server/WindowManagerService.java
index 3fa5baf..26e34aa 100644
--- a/services/java/com/android/server/WindowManagerService.java
+++ b/services/java/com/android/server/WindowManagerService.java
@@ -63,6 +63,7 @@ import android.os.Binder;
 import android.os.Debug;
 import android.os.Handler;
 import android.os.IBinder;
+import android.os.LatencyTimer;
 import android.os.LocalPowerManager;
 import android.os.Looper;
 import android.os.Message;
@@ -133,7 +134,9 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
     static final boolean DEBUG_STARTING_WINDOW = false;
     static final boolean DEBUG_REORDER = false;
     static final boolean SHOW_TRANSACTIONS = false;
-    
+    static final boolean MEASURE_LATENCY = false;
+    static private LatencyTimer lt;
+
     static final boolean PROFILE_ORIENTATION = false;
     static final boolean BLUR = true;
     static final boolean localLOGV = DEBUG;
@@ -495,6 +498,10 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
 
     private WindowManagerService(Context context, PowerManagerService pm,
             boolean haveInputMethods) {
+        if (MEASURE_LATENCY) {
+            lt = new LatencyTimer(100, 1000);
+        }
+        
         mContext = context;
         mHaveInputMethods = haveInputMethods;
         mLimitedAlphaCompositing = context.getResources().getBoolean(
@@ -3775,9 +3782,17 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
         if (DEBUG_INPUT || WindowManagerPolicy.WATCH_POINTER) Log.v(TAG,
                 "dispatchPointer " + ev);
 
+        if (MEASURE_LATENCY) {
+            lt.sample("3 Wait for last dispatch ", System.nanoTime() - qev.whenNano);
+        }
+
         Object targetObj = mKeyWaiter.waitForNextEventTarget(null, qev,
                 ev, true, false);
         
+        if (MEASURE_LATENCY) {
+            lt.sample("3 Last dispatch finished ", System.nanoTime() - qev.whenNano);
+        }
+
         int action = ev.getAction();
         
         if (action == MotionEvent.ACTION_UP) {
@@ -3814,6 +3829,7 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
         WindowState target = (WindowState)targetObj;
         
         final long eventTime = ev.getEventTime();
+        final long eventTimeNano = ev.getEventTimeNano();
         
         //Log.i(TAG, "Sending " + ev + " to " + target);
 
@@ -3832,6 +3848,10 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
             }
         }
         
+        if (MEASURE_LATENCY) {
+            lt.sample("4 in dispatchPointer     ", System.nanoTime() - eventTimeNano);
+        }
+
         if ((target.mAttrs.flags & 
                         WindowManager.LayoutParams.FLAG_IGNORE_CHEEK_PRESSES) != 0) {
             //target wants to ignore fat touch events
@@ -3914,6 +3934,10 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
             }
         }
 
+        if (MEASURE_LATENCY) {
+            lt.sample("5 in dispatchPointer     ", System.nanoTime() - eventTimeNano);
+        }
+
         synchronized(mWindowMap) {
             if (qev != null && action == MotionEvent.ACTION_MOVE) {
                 mKeyWaiter.bindTargetWindowLocked(target,
@@ -3951,7 +3975,16 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
             if (DEBUG_INPUT || DEBUG_FOCUS || WindowManagerPolicy.WATCH_POINTER) {
                 Log.v(TAG, "Delivering pointer " + qev + " to " + target);
             }
+            
+            if (MEASURE_LATENCY) {
+                lt.sample("6 before svr->client ipc ", System.nanoTime() - eventTimeNano);
+            }
+
             target.mClient.dispatchPointer(ev, eventTime);
+
+            if (MEASURE_LATENCY) {
+                lt.sample("7 after  svr->client ipc ", System.nanoTime() - eventTimeNano);
+            }
             return true;
         } catch (android.os.RemoteException e) {
             Log.i(TAG, "WINDOW DIED during motion dispatch: " + target);
@@ -5072,7 +5105,7 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
                 }
             }
         }
-    };
+    }
 
     public boolean detectSafeMode() {
         mSafeMode = mPolicy.detectSafeMode();
@@ -5137,9 +5170,13 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
                 if (DEBUG_INPUT && ev != null) Log.v(
                         TAG, "Event: type=" + ev.classType + " data=" + ev.event);
 
+                if (MEASURE_LATENCY) {
+                    lt.sample("2 got event              ", System.nanoTime() - ev.whenNano);
+                }
+
                 try {
                     if (ev != null) {
-                        curTime = ev.when;
+                        curTime = SystemClock.uptimeMillis();
                         int eventType;
                         if (ev.classType == RawInputEvent.CLASS_TOUCHSCREEN) {
                             eventType = eventType((MotionEvent)ev.event);
@@ -5150,11 +5187,9 @@ public class WindowManagerService extends IWindowManager.Stub implements Watchdo
                             eventType = LocalPowerManager.OTHER_EVENT;
                         }
                         try {
-                            long now = SystemClock.uptimeMillis();
-
-                            if ((now - mLastBatteryStatsCallTime)
+                            if ((curTime - mLastBatteryStatsCallTime)
                                     >= MIN_TIME_BETWEEN_USERACTIVITIES) {
-                                mLastBatteryStatsCallTime = now;
+                                mLastBatteryStatsCallTime = curTime;
                                 mBatteryStats.noteInputEvent();
                             }
                         } catch (RemoteException e) {