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
This commit is contained in:
Michael Chan
2009-05-13 17:29:48 -07:00
parent 4eebf590a3
commit 53071d6d15
6 changed files with 270 additions and 27 deletions

View File

@@ -0,0 +1,94 @@
/*
* Copyright (C) 2009 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package android.os;
import android.util.Log;
import java.util.HashMap;
/**
* A class to help with measuring latency in your code.
*
* Suggested usage:
* 1) Instanciate a LatencyTimer as a class field.
* private [static] LatencyTimer mLt = new LatencyTimer(100, 1000);
* 2) At various points in the code call sample with a string and the time delta to some fixed time.
* The string should be unique at each point of the code you are measuring.
* mLt.sample("before processing event", System.nanoTime() - event.getEventTimeNano());
* processEvent(event);
* mLt.sample("after processing event ", System.nanoTime() - event.getEventTimeNano());
*
* @hide
*/
public final class LatencyTimer
{
final String TAG = "LatencyTimer";
final int mSampleSize;
final int mScaleFactor;
volatile HashMap<String, long[]> store = new HashMap<String, long[]>();
/**
* Creates a LatencyTimer object
* @param sampleSize number of samples to collect before printing out the average
* @param scaleFactor divisor used to make each sample smaller to prevent overflow when
* (sampleSize * average sample value)/scaleFactor > Long.MAX_VALUE
*/
public LatencyTimer(int sampleSize, int scaleFactor) {
if (scaleFactor == 0) {
scaleFactor = 1;
}
mScaleFactor = scaleFactor;
mSampleSize = sampleSize;
}
/**
* Add a sample delay for averaging.
* @param tag string used for printing out the result. This should be unique at each point of
* this called.
* @param delta time difference from an unique point of reference for a particular iteration
*/
public void sample(String tag, long delta) {
long[] array = getArray(tag);
// array[mSampleSize] holds the number of used entries
final int index = (int) array[mSampleSize]++;
array[index] = delta;
if (array[mSampleSize] == mSampleSize) {
long totalDelta = 0;
for (long d : array) {
totalDelta += d/mScaleFactor;
}
array[mSampleSize] = 0;
Log.i(TAG, tag + " average = " + totalDelta / mSampleSize);
}
}
private long[] getArray(String tag) {
long[] data = store.get(tag);
if (data == null) {
synchronized(store) {
data = store.get(tag);
if (data == null) {
data = new long[mSampleSize + 1];
store.put(tag, data);
data[mSampleSize] = 0;
}
}
}
return data;
}
}

View File

@@ -19,7 +19,6 @@ package android.view;
import android.os.Parcel;
import android.os.Parcelable;
import android.os.SystemClock;
import android.util.Config;
/**
* Object used to report movement (mouse, pen, finger, trackball) events. This
@@ -87,6 +86,7 @@ public final class MotionEvent implements Parcelable {
private long mDownTime;
private long mEventTime;
private long mEventTimeNano;
private int mAction;
private float mX;
private float mY;
@@ -123,6 +123,62 @@ public final class MotionEvent implements Parcelable {
return ev;
}
}
/**
* Create a new MotionEvent, filling in all of the basic values that
* define the motion.
*
* @param downTime The time (in ms) when the user originally pressed down to start
* a stream of position events. This must be obtained from {@link SystemClock#uptimeMillis()}.
* @param eventTime The the time (in ms) when this specific event was generated. This
* must be obtained from {@link SystemClock#uptimeMillis()}.
* @param eventTimeNano The the time (in ns) when this specific event was generated. This
* must be obtained from {@link System#nanoTime()}.
* @param action The kind of action being performed -- one of either
* {@link #ACTION_DOWN}, {@link #ACTION_MOVE}, {@link #ACTION_UP}, or
* {@link #ACTION_CANCEL}.
* @param x The X coordinate of this event.
* @param y The Y coordinate of this event.
* @param pressure The current pressure of this event. The pressure generally
* ranges from 0 (no pressure at all) to 1 (normal pressure), however
* values higher than 1 may be generated depending on the calibration of
* the input device.
* @param size A scaled value of the approximate size of the area being pressed when
* touched with the finger. The actual value in pixels corresponding to the finger
* touch is normalized with a device specific range of values
* and scaled to a value between 0 and 1.
* @param metaState The state of any meta / modifier keys that were in effect when
* the event was generated.
* @param xPrecision The precision of the X coordinate being reported.
* @param yPrecision The precision of the Y coordinate being reported.
* @param deviceId The id for the device that this event came from. An id of
* zero indicates that the event didn't come from a physical device; other
* numbers are arbitrary and you shouldn't depend on the values.
* @param edgeFlags A bitfield indicating which edges, if any, where touched by this
* MotionEvent.
*
* @hide
*/
static public MotionEvent obtainNano(long downTime, long eventTime, long eventTimeNano,
int action, float x, float y, float pressure, float size, int metaState,
float xPrecision, float yPrecision, int deviceId, int edgeFlags) {
MotionEvent ev = obtain();
ev.mDeviceId = deviceId;
ev.mEdgeFlags = edgeFlags;
ev.mDownTime = downTime;
ev.mEventTime = eventTime;
ev.mEventTimeNano = eventTimeNano;
ev.mAction = action;
ev.mX = ev.mRawX = x;
ev.mY = ev.mRawY = y;
ev.mPressure = pressure;
ev.mSize = size;
ev.mMetaState = metaState;
ev.mXPrecision = xPrecision;
ev.mYPrecision = yPrecision;
return ev;
}
/**
* Create a new MotionEvent, filling in all of the basic values that
@@ -163,6 +219,7 @@ public final class MotionEvent implements Parcelable {
ev.mEdgeFlags = edgeFlags;
ev.mDownTime = downTime;
ev.mEventTime = eventTime;
ev.mEventTimeNano = eventTime * 1000000;
ev.mAction = action;
ev.mX = ev.mRawX = x;
ev.mY = ev.mRawY = y;
@@ -199,6 +256,7 @@ public final class MotionEvent implements Parcelable {
ev.mEdgeFlags = 0;
ev.mDownTime = downTime;
ev.mEventTime = eventTime;
ev.mEventTimeNano = eventTime * 1000000;
ev.mAction = action;
ev.mX = ev.mRawX = x;
ev.mY = ev.mRawY = y;
@@ -246,6 +304,7 @@ public final class MotionEvent implements Parcelable {
ev.mEdgeFlags = o.mEdgeFlags;
ev.mDownTime = o.mDownTime;
ev.mEventTime = o.mEventTime;
ev.mEventTimeNano = o.mEventTimeNano;
ev.mAction = o.mAction;
ev.mX = o.mX;
ev.mRawX = o.mRawX;
@@ -316,6 +375,16 @@ public final class MotionEvent implements Parcelable {
return mEventTime;
}
/**
* 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 final long getEventTimeNano() {
return mEventTimeNano;
}
/**
* Returns the X coordinate of this event. Whole numbers are pixels; the
* value may have a fraction for input devices that are sub-pixel precise.
@@ -644,6 +713,7 @@ public final class MotionEvent implements Parcelable {
public void writeToParcel(Parcel out, int flags) {
out.writeLong(mDownTime);
out.writeLong(mEventTime);
out.writeLong(mEventTimeNano);
out.writeInt(mAction);
out.writeFloat(mX);
out.writeFloat(mY);
@@ -675,6 +745,7 @@ public final class MotionEvent implements Parcelable {
private void readFromParcel(Parcel in) {
mDownTime = in.readLong();
mEventTime = in.readLong();
mEventTimeNano = in.readLong();
mAction = in.readInt();
mX = in.readFloat();
mY = in.readFloat();

View File

@@ -77,6 +77,9 @@ public final class ViewRoot extends Handler implements ViewParent,
private static final boolean DEBUG_IMF = false || LOCAL_LOGV;
private static final boolean WATCH_POINTER = false;
private static final boolean MEASURE_LATENCY = false;
private static LatencyTimer lt;
/**
* Maximum time we allow the user to roll the trackball enough to generate
* a key event, before resetting the counters.
@@ -192,6 +195,10 @@ public final class ViewRoot extends Handler implements ViewParent,
public ViewRoot(Context context) {
super();
if (MEASURE_LATENCY && lt == null) {
lt = new LatencyTimer(100, 1000);
}
++sInstanceCount;
// Initialize the statics when this class is first instantiated. This is
@@ -1579,7 +1586,17 @@ public final class ViewRoot extends Handler implements ViewParent,
boolean didFinish;
if (event == null) {
try {
long timeBeforeGettingEvents;
if (MEASURE_LATENCY) {
timeBeforeGettingEvents = System.nanoTime();
}
event = sWindowSession.getPendingPointerMove(mWindow);
if (MEASURE_LATENCY && event != null) {
lt.sample("9 Client got events ", System.nanoTime() - event.getEventTimeNano());
lt.sample("8 Client getting events ", timeBeforeGettingEvents - event.getEventTimeNano());
}
} catch (RemoteException e) {
}
didFinish = true;
@@ -1603,7 +1620,13 @@ public final class ViewRoot extends Handler implements ViewParent,
captureMotionLog("captureDispatchPointer", event);
}
event.offsetLocation(0, mCurScrollY);
if (MEASURE_LATENCY) {
lt.sample("A Dispatching TouchEvents", System.nanoTime() - event.getEventTimeNano());
}
handled = mView.dispatchTouchEvent(event);
if (MEASURE_LATENCY) {
lt.sample("B Dispatched TouchEvents ", System.nanoTime() - event.getEventTimeNano());
}
if (!handled && isDown) {
int edgeSlop = mViewConfiguration.getScaledEdgeSlop();
@@ -2685,7 +2708,11 @@ public final class ViewRoot extends Handler implements ViewParent,
public void dispatchPointer(MotionEvent event, long eventTime) {
final ViewRoot viewRoot = mViewRoot.get();
if (viewRoot != null) {
if (viewRoot != null) {
if (MEASURE_LATENCY) {
// Note: eventTime is in milliseconds
ViewRoot.lt.sample("* ViewRoot b4 dispatchPtr", System.nanoTime() - eventTime * 1000000);
}
viewRoot.dispatchPointer(event, eventTime);
} else {
new EventCompletion(mMainLooper, this, null, true, event);

View File

@@ -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);

View File

@@ -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);
}
}
}

View File

@@ -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) {