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

Commit a37bad12 authored by Prabir Pradhan's avatar Prabir Pradhan
Browse files

Improve existing InputDispatcher traces 

Previously, we traced using ATRACE_NAME inside an
if condition after checking if atrace was enabled. This was so that we
could avoid the addtional overhead of formatting the trace string when
there's no ongoing trace.

Since ATRACE_NAME is expected to be scoped trace of the call, doing it
inside an if condition means the scope of the trace ends immediately
once we leave the inner scope of the conditional. This essentially makes
all of our scoped traces point traces.

We get around this by adding a new helper macro ATRACE_NAME_IF that
takes a lambda that formats the message. This way, we can avoid the
formatting overhead and ensure the entire scope of the method is traced.

Bug: 210460522
Test: manual: take a trace with Perfetto
Change-Id: Ibee1e7dc5021296bdb5871dec59d8d4978fcf0c9
parent a2235188

include/input/TraceTools.h

0 → 100644
+25 −0
Original line number Diff line number Diff line 
/*

 * Copyright 2023 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.

 */



#pragma once



#include <utils/Trace.h>

#include <optional>



#define ATRACE_NAME_IF(condition, messageProvider)                                            \

    const auto _trace_token = condition                                                       \

            ? std::make_optional<android::ScopedTrace>(ATRACE_TAG, messageProvider().c_str()) \

            : std::nullopt

libs/input/InputTransport.cpp

+35 −43
Original line number Diff line number Diff line
@@ -24,6 +24,7 @@ 
#include <utils/Trace.h>



#include <input/InputTransport.h>

#include <input/TraceTools.h>



namespace {
@@ -432,6 +433,10 @@ status_t InputChannel::openInputChannelPair(const std::string& name, 
}



status_t InputChannel::sendMessage(const InputMessage* msg) {

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("sendMessage(inputChannel=%s, seq=0x%" PRIx32 ", type=0x%" PRIx32 ")",

                            mName.c_str(), msg->header.seq, msg->header.type);

    });

    const size_t msgLength = msg->size();

    InputMessage cleanMsg;

    msg->getSanitizedCopy(&cleanMsg);
@@ -463,16 +468,13 @@ status_t InputChannel::sendMessage(const InputMessage* msg) { 
    ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ sent message of type %s", mName.c_str(),

             ftl::enum_string(msg->header.type).c_str());



    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("sendMessage(inputChannel=%s, seq=0x%" PRIx32 ", type=0x%" PRIx32 ")",

                             mName.c_str(), msg->header.seq, msg->header.type);

        ATRACE_NAME(message.c_str());

    }

    return OK;

}



status_t InputChannel::receiveMessage(InputMessage* msg) {

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("receiveMessage(inputChannel=%s)", mName.c_str());

    });

    ssize_t nRead;

    do {

        nRead = ::recv(getFd(), msg, sizeof(InputMessage), MSG_DONTWAIT);
@@ -504,8 +506,8 @@ status_t InputChannel::receiveMessage(InputMessage* msg) { 


    ALOGD_IF(DEBUG_CHANNEL_MESSAGES, "channel '%s' ~ received message of type %s", mName.c_str(),

             ftl::enum_string(msg->header.type).c_str());



    if (ATRACE_ENABLED()) {

        // Add an additional trace point to include data about the received message.

        std::string message = StringPrintf("receiveMessage(inputChannel=%s, seq=0x%" PRIx32

                                           ", type=0x%" PRIx32 ")",

                                           mName.c_str(), msg->header.seq, msg->header.type);
@@ -578,13 +580,11 @@ status_t InputPublisher::publishKeyEvent(uint32_t seq, int32_t eventId, int32_t 
                                         int32_t flags, int32_t keyCode, int32_t scanCode,

                                         int32_t metaState, int32_t repeatCount, nsecs_t downTime,

                                         nsecs_t eventTime) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("publishKeyEvent(inputChannel=%s, action=%s, keyCode=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishKeyEvent(inputChannel=%s, action=%s, keyCode=%s)",

                            mChannel->getName().c_str(), KeyEvent::actionToString(action),

                            KeyEvent::getLabel(keyCode));

        ATRACE_NAME(message.c_str());

    }

    });

    ALOGD_IF(debugTransportPublisher(),

             "channel '%s' publisher ~ %s: seq=%u, id=%d, deviceId=%d, source=%s, "

             "action=%s, flags=0x%x, keyCode=%s, scanCode=%d, metaState=0x%x, repeatCount=%d,"
@@ -626,12 +626,11 @@ status_t InputPublisher::publishMotionEvent( 
        const ui::Transform& rawTransform, nsecs_t downTime, nsecs_t eventTime,

        uint32_t pointerCount, const PointerProperties* pointerProperties,

        const PointerCoords* pointerCoords) {

    if (ATRACE_ENABLED()) {

        std::string message = StringPrintf("publishMotionEvent(inputChannel=%s, action=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishMotionEvent(inputChannel=%s, action=%s)",

                            mChannel->getName().c_str(),

                            MotionEvent::actionToString(action).c_str());

        ATRACE_NAME(message.c_str());

    }

    });

    if (verifyEvents()) {

        Result<void> result =

                mInputVerifier.processMovement(deviceId, action, pointerCount, pointerProperties,
@@ -710,11 +709,10 @@ status_t InputPublisher::publishMotionEvent( 
}



status_t InputPublisher::publishFocusEvent(uint32_t seq, int32_t eventId, bool hasFocus) {

    if (ATRACE_ENABLED()) {

        std::string message = StringPrintf("publishFocusEvent(inputChannel=%s, hasFocus=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishFocusEvent(inputChannel=%s, hasFocus=%s)",

                            mChannel->getName().c_str(), toString(hasFocus));

        ATRACE_NAME(message.c_str());

    }

    });

    ALOGD_IF(debugTransportPublisher(), "channel '%s' publisher ~ %s: seq=%u, id=%d, hasFocus=%s",

             mChannel->getName().c_str(), __func__, seq, eventId, toString(hasFocus));
@@ -728,12 +726,10 @@ status_t InputPublisher::publishFocusEvent(uint32_t seq, int32_t eventId, bool h 


status_t InputPublisher::publishCaptureEvent(uint32_t seq, int32_t eventId,

                                             bool pointerCaptureEnabled) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("publishCaptureEvent(inputChannel=%s, pointerCaptureEnabled=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishCaptureEvent(inputChannel=%s, pointerCaptureEnabled=%s)",

                            mChannel->getName().c_str(), toString(pointerCaptureEnabled));

        ATRACE_NAME(message.c_str());

    }

    });

    ALOGD_IF(debugTransportPublisher(),

             "channel '%s' publisher ~ %s: seq=%u, id=%d, pointerCaptureEnabled=%s",

             mChannel->getName().c_str(), __func__, seq, eventId, toString(pointerCaptureEnabled));
@@ -748,12 +744,10 @@ status_t InputPublisher::publishCaptureEvent(uint32_t seq, int32_t eventId, 


status_t InputPublisher::publishDragEvent(uint32_t seq, int32_t eventId, float x, float y,

                                          bool isExiting) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("publishDragEvent(inputChannel=%s, x=%f, y=%f, isExiting=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishDragEvent(inputChannel=%s, x=%f, y=%f, isExiting=%s)",

                            mChannel->getName().c_str(), x, y, toString(isExiting));

        ATRACE_NAME(message.c_str());

    }

    });

    ALOGD_IF(debugTransportPublisher(),

             "channel '%s' publisher ~ %s: seq=%u, id=%d, x=%f, y=%f, isExiting=%s",

             mChannel->getName().c_str(), __func__, seq, eventId, x, y, toString(isExiting));
@@ -769,12 +763,10 @@ status_t InputPublisher::publishDragEvent(uint32_t seq, int32_t eventId, float x 
}



status_t InputPublisher::publishTouchModeEvent(uint32_t seq, int32_t eventId, bool isInTouchMode) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("publishTouchModeEvent(inputChannel=%s, isInTouchMode=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("publishTouchModeEvent(inputChannel=%s, isInTouchMode=%s)",

                            mChannel->getName().c_str(), toString(isInTouchMode));

        ATRACE_NAME(message.c_str());

    }

    });

    ALOGD_IF(debugTransportPublisher(),

             "channel '%s' publisher ~ %s: seq=%u, id=%d, isInTouchMode=%s",

             mChannel->getName().c_str(), __func__, seq, eventId, toString(isInTouchMode));

services/inputflinger/dispatcher/InputDispatcher.cpp

+22 −29
Original line number Diff line number Diff line
@@ -32,6 +32,7 @@ 
#endif

#include <input/InputDevice.h>

#include <input/PrintTools.h>

#include <input/TraceTools.h>

#include <openssl/mem.h>

#include <powermanager/PowerManager.h>

#include <unistd.h>
@@ -3161,12 +3162,10 @@ void InputDispatcher::prepareDispatchCycleLocked(nsecs_t currentTime, 
                                                 const std::shared_ptr<Connection>& connection,

                                                 std::shared_ptr<EventEntry> eventEntry,

                                                 const InputTarget& inputTarget) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("prepareDispatchCycleLocked(inputChannel=%s, id=0x%" PRIx32 ")",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("prepareDispatchCycleLocked(inputChannel=%s, id=0x%" PRIx32 ")",

                            connection->getInputChannelName().c_str(), eventEntry->id);

        ATRACE_NAME(message.c_str());

    }

    });

    if (DEBUG_DISPATCH_CYCLE) {

        ALOGD("channel '%s' ~ prepareDispatchCycle - flags=%s, "

              "globalScaleFactor=%f, pointerIds=%s %s",
@@ -3231,12 +3230,10 @@ void InputDispatcher::enqueueDispatchEntriesLocked(nsecs_t currentTime, 
                                                   const std::shared_ptr<Connection>& connection,

                                                   std::shared_ptr<EventEntry> eventEntry,

                                                   const InputTarget& inputTarget) {

    if (ATRACE_ENABLED()) {

        std::string message =

                StringPrintf("enqueueDispatchEntriesLocked(inputChannel=%s, id=0x%" PRIx32 ")",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("enqueueDispatchEntriesLocked(inputChannel=%s, id=0x%" PRIx32 ")",

                            connection->getInputChannelName().c_str(), eventEntry->id);

        ATRACE_NAME(message.c_str());

    }

    });

    LOG_ALWAYS_FATAL_IF(!inputTarget.flags.any(InputTarget::DISPATCH_MASK),

                        "No dispatch flags are set for %s", eventEntry->getDescription().c_str());
@@ -3266,12 +3263,11 @@ void InputDispatcher::enqueueDispatchEntryLocked(const std::shared_ptr<Connectio 
                                                 std::shared_ptr<EventEntry> eventEntry,

                                                 const InputTarget& inputTarget,

                                                 ftl::Flags<InputTarget::Flags> dispatchMode) {

    if (ATRACE_ENABLED()) {

        std::string message = StringPrintf("enqueueDispatchEntry(inputChannel=%s, dispatchMode=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("enqueueDispatchEntry(inputChannel=%s, dispatchMode=%s)",

                            connection->getInputChannelName().c_str(),

                            dispatchMode.string().c_str());

        ATRACE_NAME(message.c_str());

    }

    });

    ftl::Flags<InputTarget::Flags> inputTargetFlags = inputTarget.flags;

    if (!inputTargetFlags.any(dispatchMode)) {

        return;
@@ -3558,11 +3554,10 @@ status_t InputDispatcher::publishMotionEvent(Connection& connection, 


void InputDispatcher::startDispatchCycleLocked(nsecs_t currentTime,

                                               const std::shared_ptr<Connection>& connection) {

    if (ATRACE_ENABLED()) {

        std::string message = StringPrintf("startDispatchCycleLocked(inputChannel=%s)",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("startDispatchCycleLocked(inputChannel=%s)",

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

        ATRACE_NAME(message.c_str());

    }

    });

    if (DEBUG_DISPATCH_CYCLE) {

        ALOGD("channel '%s' ~ startDispatchCycle", connection->getInputChannelName().c_str());

    }
@@ -4136,12 +4131,10 @@ std::unique_ptr<MotionEntry> InputDispatcher::splitMotionEvent( 
    }



    int32_t newId = mIdGenerator.nextId();

    if (ATRACE_ENABLED()) {

        std::string message = StringPrintf("Split MotionEvent(id=0x%" PRIx32

                                           ") to MotionEvent(id=0x%" PRIx32 ").",

    ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {

        return StringPrintf("Split MotionEvent(id=0x%" PRIx32 ") to MotionEvent(id=0x%" PRIx32 ").",

                            originalMotionEntry.id, newId);

        ATRACE_NAME(message.c_str());

    }

    });

    std::unique_ptr<MotionEntry> splitMotionEntry =

            std::make_unique<MotionEntry>(newId, originalMotionEntry.eventTime,

                                          originalMotionEntry.deviceId, originalMotionEntry.source,