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
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 @@
}
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 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 c282e4bb..13d8809 100755
--- a/core/java/android/view/KeyEvent.java
+++ b/core/java/android/view/KeyEvent.java
@@ -2340,6 +2340,12 @@
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 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 @@
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 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 @@
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 @@
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 @@
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 @@
}
}
- 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 @@
}
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 @@
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 @@
}
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 @@
}
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 @@
}
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 @@
}
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 @@
private void finishKeyEvent(KeyEvent event, boolean sendDone, boolean handled) {
if (sendDone) {
- finishInputEvent(handled);
+ finishInputEvent(event, handled);
}
}
@@ -3262,16 +3373,19 @@
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);
}
};
diff --git a/libs/ui/InputTransport.cpp b/libs/ui/InputTransport.cpp
index 9d1b8b9..93d0d1f 100644
--- a/libs/ui/InputTransport.cpp
+++ b/libs/ui/InputTransport.cpp
@@ -27,8 +27,14 @@
namespace android {
+#define ROUND_UP(value, boundary) (((value) + (boundary) - 1) & ~((boundary) - 1))
+#define MIN_HISTORY_DEPTH 20
+
// Must be at least sizeof(InputMessage) + sufficient space for pointer data
-static const int DEFAULT_MESSAGE_BUFFER_SIZE = 16384;
+static const int DEFAULT_MESSAGE_BUFFER_SIZE = ROUND_UP(
+ sizeof(InputMessage) + MIN_HISTORY_DEPTH
+ * (sizeof(InputMessage::SampleData) + MAX_POINTERS * sizeof(PointerCoords)),
+ 4096);
// Signal sent by the producer to the consumer to inform it that a new message is
// available to be consumed in the shared memory buffer.
diff --git a/services/input/EventHub.cpp b/services/input/EventHub.cpp
index 9a9d9e5..ff4b11a 100644
--- a/services/input/EventHub.cpp
+++ b/services/input/EventHub.cpp
@@ -539,7 +539,24 @@
(int) iev.time.tv_sec, (int) iev.time.tv_usec,
iev.type, iev.code, iev.value);
+#ifdef HAVE_POSIX_CLOCKS
+ // Use the time specified in the event instead of the current time
+ // so that downstream code can get more accurate estimates of
+ // event dispatch latency from the time the event is enqueued onto
+ // the evdev client buffer.
+ //
+ // The event's timestamp fortuitously uses the same monotonic clock
+ // time base as the rest of Android. The kernel event device driver
+ // (drivers/input/evdev.c) obtains timestamps using ktime_get_ts().
+ // The systemTime(SYSTEM_TIME_MONOTONIC) function we use everywhere
+ // calls clock_gettime(CLOCK_MONOTONIC) which is implemented as a
+ // system call that also queries ktime_get_ts().
+ event->when = nsecs_t(iev.time.tv_sec) * 1000000000LL
+ + nsecs_t(iev.time.tv_usec) * 1000LL;
+ LOGV("event time %lld, now %lld", event->when, now);
+#else
event->when = now;
+#endif
event->deviceId = deviceId;
event->type = iev.type;
event->scanCode = iev.code;
diff --git a/services/input/InputDispatcher.cpp b/services/input/InputDispatcher.cpp
index 810b709..46de933 100644
--- a/services/input/InputDispatcher.cpp
+++ b/services/input/InputDispatcher.cpp
@@ -79,6 +79,22 @@
// before considering it stale and dropping it.
const nsecs_t STALE_EVENT_TIMEOUT = 10000 * 1000000LL; // 10sec
+// Motion samples that are received within this amount of time are simply coalesced
+// when batched instead of being appended. This is done because some drivers update
+// the location of pointers one at a time instead of all at once.
+// For example, when there are 10 fingers down, the input dispatcher may receive 10
+// samples in quick succession with only one finger's location changed in each sample.
+//
+// This value effectively imposes an upper bound on the touch sampling rate.
+// Touch sensors typically have a 50Hz - 200Hz sampling rate, so we expect distinct
+// samples to become available 5-20ms apart but individual finger reports can trickle
+// in over a period of 2-4ms or so.
+//
+// Empirical testing shows that a 2ms coalescing interval (500Hz) is not enough,
+// a 3ms coalescing interval (333Hz) works well most of the time and doesn't introduce
+// significant quantization noise on current hardware.
+const nsecs_t MOTION_SAMPLE_COALESCE_INTERVAL = 3 * 1000000LL; // 3ms, 333Hz
+
static inline nsecs_t now() {
return systemTime(SYSTEM_TIME_MONOTONIC);
@@ -2505,21 +2521,15 @@
continue;
}
- if (motionEntry->action != action
- || motionEntry->pointerCount != pointerCount
- || motionEntry->isInjected()) {
+ if (!motionEntry->canAppendSamples(action, pointerCount, pointerIds)) {
// Last motion event in the queue for this device and source is
// not compatible for appending new samples. Stop here.
goto NoBatchingOrStreaming;
}
- // The last motion event is a move and is compatible for appending.
// Do the batching magic.
- mAllocator.appendMotionSample(motionEntry, eventTime, pointerCoords);
-#if DEBUG_BATCHING
- LOGD("Appended motion sample onto batch for most recent "
- "motion event for this device in the inbound queue.");
-#endif
+ batchMotionLocked(motionEntry, eventTime, metaState, pointerCoords,
+ "most recent motion event for this device and source in the inbound queue");
mLock.unlock();
return; // done!
}
@@ -2534,19 +2544,15 @@
&& mPendingEvent->type == EventEntry::TYPE_MOTION) {
MotionEntry* motionEntry = static_cast<MotionEntry*>(mPendingEvent);
if (motionEntry->deviceId == deviceId && motionEntry->source == source) {
- if (motionEntry->action != action
- || motionEntry->pointerCount != pointerCount
- || motionEntry->isInjected()) {
- // Pending event is not compatible for appending new samples. Stop here.
+ if (!motionEntry->canAppendSamples(action, pointerCount, pointerIds)) {
+ // Pending motion event is for this device and source but it is
+ // not compatible for appending new samples. Stop here.
goto NoBatchingOrStreaming;
}
- // The pending motion event is a move and is compatible for appending.
// Do the batching magic.
- mAllocator.appendMotionSample(motionEntry, eventTime, pointerCoords);
-#if DEBUG_BATCHING
- LOGD("Appended motion sample onto batch for the pending motion event.");
-#endif
+ batchMotionLocked(motionEntry, eventTime, metaState, pointerCoords,
+ "pending motion event");
mLock.unlock();
return; // done!
}
@@ -2629,7 +2635,7 @@
mAllocator.appendMotionSample(motionEntry, eventTime, pointerCoords);
#if DEBUG_BATCHING
LOGD("Appended motion sample onto batch for most recently dispatched "
- "motion event for this device in the outbound queues. "
+ "motion event for this device and source in the outbound queues. "
"Attempting to stream the motion sample.");
#endif
nsecs_t currentTime = now();
@@ -2660,6 +2666,36 @@
}
}
+void InputDispatcher::batchMotionLocked(MotionEntry* entry, nsecs_t eventTime,
+ int32_t metaState, const PointerCoords* pointerCoords, const char* eventDescription) {
+ // Combine meta states.
+ entry->metaState |= metaState;
+
+ // Coalesce this sample if not enough time has elapsed since the last sample was
+ // initially appended to the batch.
+ MotionSample* lastSample = entry->lastSample;
+ long interval = eventTime - lastSample->eventTimeBeforeCoalescing;
+ if (interval <= MOTION_SAMPLE_COALESCE_INTERVAL) {
+ uint32_t pointerCount = entry->pointerCount;
+ for (uint32_t i = 0; i < pointerCount; i++) {
+ lastSample->pointerCoords[i].copyFrom(pointerCoords[i]);
+ }
+ lastSample->eventTime = eventTime;
+#if DEBUG_BATCHING
+ LOGD("Coalesced motion into last sample of batch for %s, events were %0.3f ms apart",
+ eventDescription, interval * 0.000001f);
+#endif
+ return;
+ }
+
+ // Append the sample.
+ mAllocator.appendMotionSample(entry, eventTime, pointerCoords);
+#if DEBUG_BATCHING
+ LOGD("Appended motion sample onto batch for %s, events were %0.3f ms apart",
+ eventDescription, interval * 0.000001f);
+#endif
+}
+
void InputDispatcher::notifySwitch(nsecs_t when, int32_t switchCode, int32_t switchValue,
uint32_t policyFlags) {
#if DEBUG_INBOUND_EVENT_DETAILS
@@ -3755,6 +3791,7 @@
entry->downTime = downTime;
entry->pointerCount = pointerCount;
entry->firstSample.eventTime = eventTime;
+ entry->firstSample.eventTimeBeforeCoalescing = eventTime;
entry->firstSample.next = NULL;
entry->lastSample = & entry->firstSample;
for (uint32_t i = 0; i < pointerCount; i++) {
@@ -3864,6 +3901,7 @@
nsecs_t eventTime, const PointerCoords* pointerCoords) {
MotionSample* sample = mMotionSamplePool.alloc();
sample->eventTime = eventTime;
+ sample->eventTimeBeforeCoalescing = eventTime;
uint32_t pointerCount = motionEntry->pointerCount;
for (uint32_t i = 0; i < pointerCount; i++) {
sample->pointerCoords[i].copyFrom(pointerCoords[i]);
@@ -3893,6 +3931,21 @@
return count;
}
+bool InputDispatcher::MotionEntry::canAppendSamples(int32_t action, uint32_t pointerCount,
+ const int32_t* pointerIds) const {
+ if (this->action != action
+ || this->pointerCount != pointerCount
+ || this->isInjected()) {
+ return false;
+ }
+ for (uint32_t i = 0; i < pointerCount; i++) {
+ if (this->pointerIds[i] != pointerIds[i]) {
+ return false;
+ }
+ }
+ return true;
+}
+
// --- InputDispatcher::InputState ---
diff --git a/services/input/InputDispatcher.h b/services/input/InputDispatcher.h
index 162e606..af0153b 100644
--- a/services/input/InputDispatcher.h
+++ b/services/input/InputDispatcher.h
@@ -409,7 +409,7 @@
bool dispatchInProgress; // initially false, set to true while dispatching
- inline bool isInjected() { return injectionState != NULL; }
+ inline bool isInjected() const { return injectionState != NULL; }
};
struct ConfigurationChangedEntry : EventEntry {
@@ -439,7 +439,8 @@
struct MotionSample {
MotionSample* next;
- nsecs_t eventTime;
+ nsecs_t eventTime; // may be updated during coalescing
+ nsecs_t eventTimeBeforeCoalescing; // not updated during coalescing
PointerCoords pointerCoords[MAX_POINTERS];
};
@@ -461,6 +462,10 @@
MotionSample* lastSample;
uint32_t countSamples() const;
+
+ // Checks whether we can append samples, assuming the device id and source are the same.
+ bool canAppendSamples(int32_t action, uint32_t pointerCount,
+ const int32_t* pointerIds) const;
};
// Tracks the progress of dispatching a particular event to a particular connection.
@@ -802,6 +807,11 @@
void dispatchOnceInnerLocked(nsecs_t keyRepeatTimeout, nsecs_t keyRepeatDelay,
nsecs_t* nextWakeupTime);
+ // Batches a new sample onto a motion entry.
+ // Assumes that the we have already checked that we can append samples.
+ void batchMotionLocked(MotionEntry* entry, nsecs_t eventTime, int32_t metaState,
+ const PointerCoords* pointerCoords, const char* eventDescription);
+
// Enqueues an inbound event. Returns true if mLooper->wake() should be called.
bool enqueueInboundEventLocked(EventEntry* entry);