Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit f2652121 authored by Siarhei Vishniakou's avatar Siarhei Vishniakou
Browse files

Add LatencyTracker to InputDispatcher 

LatencyTracker will be used to record the complete timeline of an input
event dispatch, from the kernel to the presentation of a graphics frame
to the display.

The data about input event timeline is coming from three different
locations:

1) notifyMotion: this is when the InputDispatcher first learns about the
event from InputReader. At this point, we learn the time when the event
was first created, to time when the event was read by the user space,
and we are now adding the timestamps when the InputReader notifies the
dispatcher about the event.

2) finishInputEvent: this is when the app sends an 'ack' that a specific
input event has been processed. Through this call, we learn about when
the event was first sent to the app, and when it was read by the app. At
this time, we are also collecting the 'finishTime', so that we can
measure the total time that the app spent processing the event.

3) sendTimeline: this is when the SurfaceFlinger notifies the app about
the metrics for a specific frame. This metrics information is passed
down through the InputChannel to the InputDispatcher. Here we learn
about the time when the app sent the buffer to the SurfaceFlinger
(gpuCompletedTime), and the time when the frame was presented
(presentTime).

Overall, the end-to-end touch latency is presentTime - eventTime.
The rest of the data can be used to measure the breakdown of this
latency.

The goal of LatencyTracker is to combine all this data and present a
complete, unified timeline for a specific input event for further data analysis.

In a separate CL, we will report this complete timeline to statsd.

Bug: 169866723
Test: atest inputflinger_tests
Change-Id: I6e6e80e3393878fe86f3935c7c0e13dfff8629f9
parent 060a7276

services/inputflinger/benchmarks/InputDispatcher_benchmarks.cpp

+6 −6
Original line number Diff line number Diff line
@@ -16,9 +16,11 @@ 


#include <benchmark/benchmark.h>



#include <android/os/IInputConstants.h>

#include <binder/Binder.h>

#include "../dispatcher/InputDispatcher.h"



using android::os::IInputConstants;

using android::os::InputEventInjectionResult;

using android::os::InputEventInjectionSync;
@@ -226,7 +228,7 @@ static MotionEvent generateMotionEvent() { 


    ui::Transform identityTransform;

    MotionEvent event;

    event.initialize(InputEvent::nextId(), DEVICE_ID, AINPUT_SOURCE_TOUCHSCREEN,

    event.initialize(IInputConstants::INVALID_INPUT_EVENT_ID, DEVICE_ID, AINPUT_SOURCE_TOUCHSCREEN,

                     ADISPLAY_ID_DEFAULT, INVALID_HMAC, AMOTION_EVENT_ACTION_DOWN,

                     /* actionButton */ 0, /* flags */ 0,

                     /* edgeFlags */ 0, AMETA_NONE, /* buttonState */ 0, MotionClassification::NONE,
@@ -252,9 +254,9 @@ static NotifyMotionArgs generateMotionArgs() { 


    const nsecs_t currentTime = now();

    // Define a valid motion event.

    NotifyMotionArgs args(/* id */ 0, currentTime, currentTime, DEVICE_ID,

                          AINPUT_SOURCE_TOUCHSCREEN, ADISPLAY_ID_DEFAULT, POLICY_FLAG_PASS_TO_USER,

                          AMOTION_EVENT_ACTION_DOWN,

    NotifyMotionArgs args(IInputConstants::INVALID_INPUT_EVENT_ID, currentTime, currentTime,

                          DEVICE_ID, AINPUT_SOURCE_TOUCHSCREEN, ADISPLAY_ID_DEFAULT,

                          POLICY_FLAG_PASS_TO_USER, AMOTION_EVENT_ACTION_DOWN,

                          /* actionButton */ 0, /* flags */ 0, AMETA_NONE, /* buttonState */ 0,

                          MotionClassification::NONE, AMOTION_EVENT_EDGE_FLAG_NONE, 1,

                          pointerProperties, pointerCoords,
@@ -283,14 +285,12 @@ static void benchmarkNotifyMotion(benchmark::State& state) { 
    for (auto _ : state) {

        // Send ACTION_DOWN

        motionArgs.action = AMOTION_EVENT_ACTION_DOWN;

        motionArgs.id = 0;

        motionArgs.downTime = now();

        motionArgs.eventTime = motionArgs.downTime;

        dispatcher->notifyMotion(&motionArgs);



        // Send ACTION_UP

        motionArgs.action = AMOTION_EVENT_ACTION_UP;

        motionArgs.id = 1;

        motionArgs.eventTime = now();

        dispatcher->notifyMotion(&motionArgs);

services/inputflinger/dispatcher/Android.bp

+2 −0
Original line number Diff line number Diff line
@@ -38,8 +38,10 @@ filegroup { 
        "InjectionState.cpp",

        "InputDispatcher.cpp",

        "InputDispatcherFactory.cpp",

        "InputEventTimeline.cpp",

        "InputState.cpp",

        "InputTarget.cpp",

        "LatencyTracker.cpp",

        "Monitor.cpp",

        "TouchState.cpp",

        "DragState.cpp",

services/inputflinger/dispatcher/Entry.h

+6 −6
Original line number Diff line number Diff line
@@ -79,7 +79,7 @@ struct ConfigurationChangedEntry : EventEntry { 
    explicit ConfigurationChangedEntry(int32_t id, nsecs_t eventTime);

    std::string getDescription() const override;



    virtual ~ConfigurationChangedEntry();

    ~ConfigurationChangedEntry() override;

};



struct DeviceResetEntry : EventEntry {
@@ -88,7 +88,7 @@ struct DeviceResetEntry : EventEntry { 
    DeviceResetEntry(int32_t id, nsecs_t eventTime, int32_t deviceId);

    std::string getDescription() const override;



    virtual ~DeviceResetEntry();

    ~DeviceResetEntry() override;

};



struct FocusEntry : EventEntry {
@@ -100,7 +100,7 @@ struct FocusEntry : EventEntry { 
               const std::string& reason);

    std::string getDescription() const override;



    virtual ~FocusEntry();

    ~FocusEntry() override;

};



struct PointerCaptureChangedEntry : EventEntry {
@@ -109,7 +109,7 @@ struct PointerCaptureChangedEntry : EventEntry { 
    PointerCaptureChangedEntry(int32_t id, nsecs_t eventTime, bool hasPointerCapture);

    std::string getDescription() const override;



    virtual ~PointerCaptureChangedEntry();

    ~PointerCaptureChangedEntry() override;

};



struct DragEntry : EventEntry {
@@ -153,7 +153,7 @@ struct KeyEntry : EventEntry { 
    std::string getDescription() const override;

    void recycle();



    virtual ~KeyEntry();

    ~KeyEntry() override;

};



struct MotionEntry : EventEntry {
@@ -204,7 +204,7 @@ struct SensorEntry : EventEntry { 
                std::vector<float> values);

    std::string getDescription() const override;



    virtual ~SensorEntry();

    ~SensorEntry() override;

};



// Tracks the progress of dispatching a particular event to a particular connection.

services/inputflinger/dispatcher/InputDispatcher.cpp

+74 −5
Original line number Diff line number Diff line
@@ -446,6 +446,56 @@ static std::optional<int32_t> findMonitorPidByToken( 
    return std::nullopt;

}



static bool shouldReportMetricsForConnection(const Connection& connection) {

    // Do not keep track of gesture monitors. They receive every event and would disproportionately

    // affect the statistics.

    if (connection.monitor) {

        return false;

    }

    // If the connection is experiencing ANR, let's skip it. We have separate ANR metrics

    if (!connection.responsive) {

        return false;

    }

    return true;

}



static bool shouldReportFinishedEvent(const DispatchEntry& dispatchEntry,

                                      const Connection& connection) {

    const EventEntry& eventEntry = *dispatchEntry.eventEntry;

    const int32_t& inputEventId = eventEntry.id;

    if (inputEventId != dispatchEntry.resolvedEventId) {

        // Event was transmuted

        return false;

    }

    if (inputEventId == android::os::IInputConstants::INVALID_INPUT_EVENT_ID) {

        return false;

    }

    // Only track latency for events that originated from hardware

    if (eventEntry.isSynthesized()) {

        return false;

    }

    const EventEntry::Type& inputEventEntryType = eventEntry.type;

    if (inputEventEntryType == EventEntry::Type::KEY) {

        const KeyEntry& keyEntry = static_cast<const KeyEntry&>(eventEntry);

        if (keyEntry.flags & AKEY_EVENT_FLAG_CANCELED) {

            return false;

        }

    } else if (inputEventEntryType == EventEntry::Type::MOTION) {

        const MotionEntry& motionEntry = static_cast<const MotionEntry&>(eventEntry);

        if (motionEntry.action == AMOTION_EVENT_ACTION_CANCEL ||

            motionEntry.action == AMOTION_EVENT_ACTION_HOVER_EXIT) {

            return false;

        }

    } else {

        // Not a key or a motion

        return false;

    }

    if (!shouldReportMetricsForConnection(connection)) {

        return false;

    }

    return true;

}



// --- InputDispatcher ---



InputDispatcher::InputDispatcher(const sp<InputDispatcherPolicyInterface>& policy)
@@ -467,6 +517,7 @@ InputDispatcher::InputDispatcher(const sp<InputDispatcherPolicyInterface>& polic 
        mFocusedDisplayId(ADISPLAY_ID_DEFAULT),

        mFocusedWindowRequestedPointerCapture(false),

        mWindowTokenWithPointerCapture(nullptr),

        mLatencyTracker(&mEmptyProcessor),

        mCompatService(getCompatService()) {

    mLooper = new Looper(false);

    mReporter = createInputReporter();
@@ -2853,6 +2904,8 @@ void InputDispatcher::enqueueDispatchEntryLocked(const sp<Connection>& connectio 
                      "event",

                      connection->getInputChannelName().c_str());

#endif

                // We keep the 'resolvedEventId' here equal to the original 'motionEntry.id' because

                // this is a one-to-one event conversion.

                dispatchEntry->resolvedAction = AMOTION_EVENT_ACTION_HOVER_ENTER;

            }
@@ -3315,7 +3368,14 @@ int InputDispatcher::handleReceiveCallback(int events, sp<IBinder> connectionTok 
                finishDispatchCycleLocked(currentTime, connection, finish.seq, finish.handled,

                                          finish.consumeTime);

            } else if (std::holds_alternative<InputPublisher::Timeline>(*result)) {

                // TODO(b/167947340): Report this data to LatencyTracker

                if (shouldReportMetricsForConnection(*connection)) {

                    const InputPublisher::Timeline& timeline =

                            std::get<InputPublisher::Timeline>(*result);

                    mLatencyTracker

                            .trackGraphicsLatency(timeline.inputEventId,

                                                  connection->inputChannel->getConnectionToken(),

                                                  std::move(timeline.graphicsTimeline));

                }

            }

            gotOne = true;

        }
@@ -3824,6 +3884,12 @@ void InputDispatcher::notifyMotion(const NotifyMotionArgs* args) { 
                                              args->xCursorPosition, args->yCursorPosition,

                                              args->downTime, args->pointerCount,

                                              args->pointerProperties, args->pointerCoords, 0, 0);

        if (args->id != android::os::IInputConstants::INVALID_INPUT_EVENT_ID &&

            IdGenerator::getSource(args->id) == IdGenerator::Source::INPUT_READER &&

            !mInputFilterEnabled) {

            const bool isDown = args->action == AMOTION_EVENT_ACTION_DOWN;

            mLatencyTracker.trackListener(args->id, isDown, args->eventTime, args->readTime);

        }



        needWake = enqueueInboundEventLocked(std::move(newEntry));

        mLock.unlock();
@@ -5047,6 +5113,7 @@ void InputDispatcher::dumpDispatchStateLocked(std::string& dump) { 
    dump += StringPrintf(INDENT2 "KeyRepeatDelay: %" PRId64 "ms\n", ns2ms(mConfig.keyRepeatDelay));

    dump += StringPrintf(INDENT2 "KeyRepeatTimeout: %" PRId64 "ms\n",

                         ns2ms(mConfig.keyRepeatTimeout));

    dump += mLatencyTracker.dump(INDENT2);

}



void InputDispatcher::dumpMonitors(std::string& dump, const std::vector<Monitor>& monitors) {
@@ -5620,10 +5687,12 @@ void InputDispatcher::doDispatchCycleFinishedLockedInterruptible(CommandEntry* c 
        ALOGI("%s spent %" PRId64 "ms processing %s", connection->getWindowName().c_str(),

              ns2ms(eventDuration), dispatchEntry->eventEntry->getDescription().c_str());

    }

    // TODO(b/167947340): report event latency information to the policy

    // Example: mPolicy->reportFinishedEvent(commandEntry->eventId, eventEntry.eventTime,

    //                                       dispatchEntry->deliveryTime, commandEntry->consumeTime,

    //                                       finishTime);

    if (shouldReportFinishedEvent(*dispatchEntry, *connection)) {

        mLatencyTracker.trackFinishedEvent(dispatchEntry->eventEntry->id,

                                           connection->inputChannel->getConnectionToken(),

                                           dispatchEntry->deliveryTime, commandEntry->consumeTime,

                                           finishTime);

    }



    bool restartEvent;

    if (dispatchEntry->eventEntry->type == EventEntry::Type::KEY) {

services/inputflinger/dispatcher/InputDispatcher.h

+8 −0
Original line number Diff line number Diff line
@@ -29,6 +29,7 @@ 
#include "InputState.h"

#include "InputTarget.h"

#include "InputThread.h"

#include "LatencyTracker.h"

#include "Monitor.h"

#include "TouchState.h"

#include "TouchedWindow.h"
@@ -635,6 +636,13 @@ private: 
    void doOnPointerDownOutsideFocusLockedInterruptible(CommandEntry* commandEntry) REQUIRES(mLock);



    // Statistics gathering.

    class EmptyTimelineProcessor : public InputEventTimelineProcessor {

        void processTimeline(const InputEventTimeline& timeline) override {

            // TODO(b/167947340): report latency information to the real aggregator

        }

    } mEmptyProcessor GUARDED_BY(mLock);



    LatencyTracker mLatencyTracker GUARDED_BY(mLock);

    void traceInboundQueueLengthLocked() REQUIRES(mLock);

    void traceOutboundQueueLength(const Connection& connection);

    void traceWaitQueueLength(const Connection& connection);