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
diff --git a/include/input/TraceTools.h b/include/input/TraceTools.h
new file mode 100644
index 0000000..70b23c5
--- /dev/null
+++ b/include/input/TraceTools.h
@@ -0,0 +1,25 @@
+/*
+ * 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
diff --git a/libs/input/InputTransport.cpp b/libs/input/InputTransport.cpp
index 3446540..843ef27 100644
--- a/libs/input/InputTransport.cpp
+++ b/libs/input/InputTransport.cpp
@@ -24,6 +24,7 @@
#include <utils/Trace.h>
#include <input/InputTransport.h>
+#include <input/TraceTools.h>
namespace {
@@ -432,6 +433,10 @@
}
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 @@
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 @@
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 @@
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)",
- mChannel->getName().c_str(), KeyEvent::actionToString(action),
- KeyEvent::getLabel(keyCode));
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishKeyEvent(inputChannel=%s, action=%s, keyCode=%s)",
+ mChannel->getName().c_str(), KeyEvent::actionToString(action),
+ KeyEvent::getLabel(keyCode));
+ });
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 @@
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)",
- mChannel->getName().c_str(),
- MotionEvent::actionToString(action).c_str());
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishMotionEvent(inputChannel=%s, action=%s)",
+ mChannel->getName().c_str(),
+ MotionEvent::actionToString(action).c_str());
+ });
if (verifyEvents()) {
Result<void> result =
mInputVerifier.processMovement(deviceId, action, pointerCount, pointerProperties,
@@ -710,11 +709,10 @@
}
status_t InputPublisher::publishFocusEvent(uint32_t seq, int32_t eventId, bool hasFocus) {
- if (ATRACE_ENABLED()) {
- std::string message = StringPrintf("publishFocusEvent(inputChannel=%s, hasFocus=%s)",
- mChannel->getName().c_str(), toString(hasFocus));
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishFocusEvent(inputChannel=%s, hasFocus=%s)",
+ mChannel->getName().c_str(), toString(hasFocus));
+ });
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::publishCaptureEvent(uint32_t seq, int32_t eventId,
bool pointerCaptureEnabled) {
- if (ATRACE_ENABLED()) {
- std::string message =
- StringPrintf("publishCaptureEvent(inputChannel=%s, pointerCaptureEnabled=%s)",
- mChannel->getName().c_str(), toString(pointerCaptureEnabled));
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishCaptureEvent(inputChannel=%s, pointerCaptureEnabled=%s)",
+ mChannel->getName().c_str(), toString(pointerCaptureEnabled));
+ });
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::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)",
- mChannel->getName().c_str(), x, y, toString(isExiting));
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishDragEvent(inputChannel=%s, x=%f, y=%f, isExiting=%s)",
+ mChannel->getName().c_str(), x, y, toString(isExiting));
+ });
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::publishTouchModeEvent(uint32_t seq, int32_t eventId, bool isInTouchMode) {
- if (ATRACE_ENABLED()) {
- std::string message =
- StringPrintf("publishTouchModeEvent(inputChannel=%s, isInTouchMode=%s)",
- mChannel->getName().c_str(), toString(isInTouchMode));
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("publishTouchModeEvent(inputChannel=%s, isInTouchMode=%s)",
+ mChannel->getName().c_str(), toString(isInTouchMode));
+ });
ALOGD_IF(debugTransportPublisher(),
"channel '%s' publisher ~ %s: seq=%u, id=%d, isInTouchMode=%s",
mChannel->getName().c_str(), __func__, seq, eventId, toString(isInTouchMode));
diff --git a/services/inputflinger/dispatcher/InputDispatcher.cpp b/services/inputflinger/dispatcher/InputDispatcher.cpp
index 630542f..b427c73 100644
--- a/services/inputflinger/dispatcher/InputDispatcher.cpp
+++ b/services/inputflinger/dispatcher/InputDispatcher.cpp
@@ -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 @@
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 ")",
- connection->getInputChannelName().c_str(), eventEntry->id);
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("prepareDispatchCycleLocked(inputChannel=%s, id=0x%" PRIx32 ")",
+ connection->getInputChannelName().c_str(), eventEntry->id);
+ });
if (DEBUG_DISPATCH_CYCLE) {
ALOGD("channel '%s' ~ prepareDispatchCycle - flags=%s, "
"globalScaleFactor=%f, pointerIds=%s %s",
@@ -3231,12 +3230,10 @@
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 ")",
- connection->getInputChannelName().c_str(), eventEntry->id);
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("enqueueDispatchEntriesLocked(inputChannel=%s, id=0x%" PRIx32 ")",
+ connection->getInputChannelName().c_str(), eventEntry->id);
+ });
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 @@
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)",
- connection->getInputChannelName().c_str(),
- dispatchMode.string().c_str());
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("enqueueDispatchEntry(inputChannel=%s, dispatchMode=%s)",
+ connection->getInputChannelName().c_str(),
+ dispatchMode.string().c_str());
+ });
ftl::Flags<InputTarget::Flags> inputTargetFlags = inputTarget.flags;
if (!inputTargetFlags.any(dispatchMode)) {
return;
@@ -3558,11 +3554,10 @@
void InputDispatcher::startDispatchCycleLocked(nsecs_t currentTime,
const std::shared_ptr<Connection>& connection) {
- if (ATRACE_ENABLED()) {
- std::string message = StringPrintf("startDispatchCycleLocked(inputChannel=%s)",
- connection->getInputChannelName().c_str());
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("startDispatchCycleLocked(inputChannel=%s)",
+ connection->getInputChannelName().c_str());
+ });
if (DEBUG_DISPATCH_CYCLE) {
ALOGD("channel '%s' ~ startDispatchCycle", connection->getInputChannelName().c_str());
}
@@ -4136,12 +4131,10 @@
}
int32_t newId = mIdGenerator.nextId();
- if (ATRACE_ENABLED()) {
- std::string message = StringPrintf("Split MotionEvent(id=0x%" PRIx32
- ") to MotionEvent(id=0x%" PRIx32 ").",
- originalMotionEntry.id, newId);
- ATRACE_NAME(message.c_str());
- }
+ ATRACE_NAME_IF(ATRACE_ENABLED(), [&]() {
+ return StringPrintf("Split MotionEvent(id=0x%" PRIx32 ") to MotionEvent(id=0x%" PRIx32 ").",
+ originalMotionEntry.id, newId);
+ });
std::unique_ptr<MotionEntry> splitMotionEntry =
std::make_unique<MotionEntry>(newId, originalMotionEntry.eventTime,
originalMotionEntry.deviceId, originalMotionEntry.source,