diff --git a/core/java/android/view/HardwareRenderer.java b/core/java/android/view/HardwareRenderer.java index 28541fe7e6387..66f37f29b0bd3 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 87e7ea7bd646b..01ddcc9bf1a41 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 c282e4bb2fbee..13d880970bf1a 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 c19a107ec749d..89736d643cf39 100644 --- a/core/java/android/view/ViewDebug.java +++ b/core/java/android/view/ViewDebug.java @@ -140,6 +140,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; + /** *

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 diff --git a/core/java/android/view/ViewRoot.java b/core/java/android/view/ViewRoot.java index 2f9d501c28ce4..a899b4631f093 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); } }; diff --git a/libs/ui/InputTransport.cpp b/libs/ui/InputTransport.cpp index 9d1b8b94ecc2b..93d0d1f8a1bc7 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 9a9d9e51330ba..ff4b11a937f84 100644 --- a/services/input/EventHub.cpp +++ b/services/input/EventHub.cpp @@ -539,7 +539,24 @@ size_t EventHub::getEvents(int timeoutMillis, RawEvent* buffer, size_t bufferSiz (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 810b7091da364..46de93310754f 100644 --- a/services/input/InputDispatcher.cpp +++ b/services/input/InputDispatcher.cpp @@ -79,6 +79,22 @@ const nsecs_t APP_SWITCH_TIMEOUT = 500 * 1000000LL; // 0.5sec // 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 @@ void InputDispatcher::notifyMotion(nsecs_t eventTime, int32_t deviceId, uint32_t 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 @@ void InputDispatcher::notifyMotion(nsecs_t eventTime, int32_t deviceId, uint32_t && mPendingEvent->type == EventEntry::TYPE_MOTION) { MotionEntry* motionEntry = static_cast(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 @@ void InputDispatcher::notifyMotion(nsecs_t eventTime, int32_t deviceId, uint32_t 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 @@ NoBatchingOrStreaming:; } } +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 @@ InputDispatcher::MotionEntry* InputDispatcher::Allocator::obtainMotionEntry(nsec 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 @@ void InputDispatcher::Allocator::appendMotionSample(MotionEntry* motionEntry, 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 @@ uint32_t InputDispatcher::MotionEntry::countSamples() const { 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 162e6066ecb58..af0153b8c2c28 100644 --- a/services/input/InputDispatcher.h +++ b/services/input/InputDispatcher.h @@ -409,7 +409,7 @@ private: 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 @@ private: 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 @@ private: 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 @@ private: 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);