[PATCH v5 3/3] binder: add transaction latency tracer

Frankie Chang
2020-06-10T12:34:13Z

From: "Frankie.Chang" <Frankie.Chang@mediatek.com>

Record start/end timestamp for binder transaction.
When transaction is completed or transaction is free,
it would be checked if transaction latency over threshold (2 sec),
if yes, printing related information for tracing.

/* Implement details */
- Add latency tracer module to monitor transaction
by attaching to new tracepoints introduced
when transactions are allocated and freed.
The trace_binder_txn_latency_free would not be enabled
by default. Monitoring which transaction is too slow to
cause some of exceptions is important. So we hook the
tracepoint to call the monitor function.

- Since some of modules would trigger timeout NE
if their binder transaction don't finish in time,
such as audio timeout (5 sec), even BT command
timeout (2 sec), etc.
Therefore, setting the timeout threshold as 2 seconds
could be helpful to debug.

- The reason why printing the related information to
kernel information log but not trace buffer is that
some abnormal transactions may be pending for a long
time ago, they could not be recorded due to buffer
limited.

Signed-off-by: Frankie.Chang <Frankie.Chang@mediatek.com>
---
drivers/android/Kconfig | 8 +++
drivers/android/Makefile | 1 +
drivers/android/binder.c | 2 +
drivers/android/binder_internal.h | 13 ++++
drivers/android/binder_latency_tracer.c | 107 +++++++++++++++++++++++++++++++
drivers/android/binder_trace.h | 28 +++++++-
6 files changed, 156 insertions(+), 3 deletions(-)
create mode 100644 drivers/android/binder_latency_tracer.c

diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
index 6fdf2ab..39d47be 100644
--- a/drivers/android/Kconfig
+++ b/drivers/android/Kconfig
@@ -54,6 +54,14 @@ config ANDROID_BINDER_IPC_SELFTEST
exhaustively with combinations of various buffer sizes and
alignments.

+config BINDER_TRANSACTION_LATENCY_TRACKING
+ bool "Android Binder transaction tracking"
+ help
+ Used for track abnormal binder transaction which is over 2 seconds,
+ when the transaction is done or be free, this transaction would be
+ checked whether it executed overtime.
+ If yes, printing out the detailed info.
+
endif # if ANDROID

endmenu
diff --git a/drivers/android/Makefile b/drivers/android/Makefile
index c9d3d0c9..c2ffdb6 100644
--- a/drivers/android/Makefile
+++ b/drivers/android/Makefile
@@ -4,3 +4,4 @@ ccflags-y += -I$(src) # needed for trace events
obj-$(CONFIG_ANDROID_BINDERFS) += binderfs.o
obj-$(CONFIG_ANDROID_BINDER_IPC) += binder.o binder_alloc.o
obj-$(CONFIG_ANDROID_BINDER_IPC_SELFTEST) += binder_alloc_selftest.o
+obj-$(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING) += binder_latency_tracer.o
diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index 5ec9af8..846d69b 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -2657,6 +2657,7 @@ static void binder_transaction(struct binder_proc *proc,
return_error_line = __LINE__;
goto err_alloc_t_failed;
}
+ trace_binder_txn_latency_alloc(t, e);
INIT_LIST_HEAD(&t->fd_fixups);
binder_stats_created(BINDER_STAT_TRANSACTION);
spin_lock_init(&t->lock);
@@ -5144,6 +5145,7 @@ static void print_binder_transaction_ilocked(struct seq_file *m,
to_proc ? to_proc->pid : 0,
t->to_thread ? t->to_thread->pid : 0,
t->code, t->flags, t->priority, t->need_reply);
+ trace_binder_txn_latency_info(m, t);
spin_unlock(&t->lock);

if (proc != to_proc) {
diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
index ed61b3e..bebc185 100644
--- a/drivers/android/binder_internal.h
+++ b/drivers/android/binder_internal.h
@@ -12,6 +12,11 @@
#include <linux/types.h>
#include <linux/uidgid.h>

+#ifdef CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING
+#include <linux/rtc.h>
+#include <linux/time.h>
+#endif
+
struct binder_context {
struct binder_node *binder_context_mgr_node;
struct mutex context_mgr_node_lock;
@@ -131,6 +136,10 @@ struct binder_transaction_log_entry {
uint32_t return_error;
uint32_t return_error_param;
char context_name[BINDERFS_MAX_NAME + 1];
+#ifdef CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING
+ struct timespec timestamp;
+ struct timeval tv;
+#endif
};

struct binder_transaction_log {
@@ -520,6 +529,10 @@ struct binder_transaction {
* during thread teardown
*/
spinlock_t lock;
+#ifdef CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING
+ struct timespec timestamp;
+ struct timeval tv;
+#endif
};

/**
diff --git a/drivers/android/binder_latency_tracer.c b/drivers/android/binder_latency_tracer.c
new file mode 100644
index 0000000..1b89634
--- /dev/null
+++ b/drivers/android/binder_latency_tracer.c
@@ -0,0 +1,107 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2019 MediaTek Inc.
+ */
+
+#include <linux/module.h>
+#include <uapi/linux/android/binder.h>
+#include "binder_alloc.h"
+#include "binder_internal.h"
+#include "binder_trace.h"
+
+/*
+ * probe_binder_txn_latency_free - Output info of a delay transaction
+ * @t: pointer to the over-time transaction
+ */
+void probe_binder_txn_latency_free(void *ignore, struct binder_transaction *t)
+{
+ struct rtc_time tm;
+ struct timespec *startime;
+ struct timespec cur, sub_t;
+
+ ktime_get_ts(&cur);
+ startime = &t->timestamp;
+ sub_t = timespec_sub(cur, *startime);
+
+ /* if transaction time is over than 2 sec,
+ * show timeout warning log.
+ */
+ if (sub_t.tv_sec < 2)
+ return;
+
+ rtc_time_to_tm(t->tv.tv_sec, &tm);
+
+ spin_lock(&t->lock);
+ pr_info_ratelimited("%d: from %d:%d to %d:%d",
+ t->debug_id,
+ t->from ? t->from->proc->pid : 0,
+ t->from ? t->from->pid : 0,
+ t->to_proc ? t->to_proc->pid : 0,
+ t->to_thread ? t->to_thread->pid : 0);
+
+ pr_info_ratelimited(" total %u.%03ld s code %u start %lu.%03ld android %d-%02d-%02d %02d:%02d:%02d.%03lu\n",
+ (unsigned int)sub_t.tv_sec,
+ (sub_t.tv_nsec / NSEC_PER_MSEC),
+ t->code,
+ (unsigned long)startime->tv_sec,
+ (startime->tv_nsec / NSEC_PER_MSEC),
+ (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
+ tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (unsigned long)(t->tv.tv_usec / USEC_PER_MSEC));
+ spin_unlock(&t->lock);
+}
+
+static void probe_binder_txn_latency_alloc(void *ignore,
+ struct binder_transaction *t,
+ struct binder_transaction_log_entry *e)
+{
+ ktime_get_ts(&e->timestamp);
+ do_gettimeofday(&e->tv);
+ e->tv.tv_sec -= (sys_tz.tz_minuteswest * 60);
+ spin_lock(&t->lock);
+ memcpy(&t->timestamp, &e->timestamp, sizeof(struct timespec));
+ memcpy(&t->tv, &e->tv, sizeof(struct timeval));
+ spin_unlock(&t->lock);
+}
+
+static void probe_binder_txn_latency_info(void *ignore, struct seq_file *m,
+ struct binder_transaction *t)
+{
+ struct rtc_time tm;
+
+ rtc_time_to_tm(t->tv.tv_sec, &tm);
+ seq_printf(m,
+ " start %lu.%06lu android %d-%02d-%02d %02d:%02d:%02d.%03lu",
+ (unsigned long)t->timestamp.tv_sec,
+ (t->timestamp.tv_nsec / NSEC_PER_USEC),
+ (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
+ tm.tm_hour, tm.tm_min, tm.tm_sec,
+ (unsigned long)(t->tv.tv_usec / USEC_PER_MSEC));
+}
+
+static int __init init_binder_latency_tracer(void)
+{
+ register_trace_binder_txn_latency_free(
+ probe_binder_txn_latency_free, NULL);
+ register_trace_binder_txn_latency_alloc(
+ probe_binder_txn_latency_alloc, NULL);
+ register_trace_binder_txn_latency_info(
+ probe_binder_txn_latency_info, NULL);
+
+ return 0;
+}
+
+static void exit_binder_latency_tracer(void)
+{
+ unregister_trace_binder_txn_latency_free(
+ probe_binder_txn_latency_free, NULL);
+ unregister_trace_binder_txn_latency_alloc(
+ probe_binder_txn_latency_alloc, NULL);
+ unregister_trace_binder_txn_latency_info(
+ probe_binder_txn_latency_info, NULL);
+}
+
+module_init(init_binder_latency_tracer);
+module_exit(exit_binder_latency_tracer);
+
+MODULE_LICENSE("GPL v2");
diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
index 8ac87d1..ca41c7d 100644
--- a/drivers/android/binder_trace.h
+++ b/drivers/android/binder_trace.h
@@ -18,6 +18,7 @@
struct binder_ref_data;
struct binder_thread;
struct binder_transaction;
+struct binder_transaction_log_entry;

TRACE_EVENT(binder_ioctl,
TP_PROTO(unsigned int cmd, unsigned long arg),
@@ -95,6 +96,18 @@
__entry->thread_todo)
);

+DECLARE_TRACE(binder_txn_latency_alloc,
+ TP_PROTO(struct binder_transaction *t,
+ struct binder_transaction_log_entry *e),
+ TP_ARGS(t, e)
+);
+
+DECLARE_TRACE(binder_txn_latency_info,
+ TP_PROTO(struct seq_file *m,
+ struct binder_transaction *t),
+ TP_ARGS(m, t)
+);
+
TRACE_EVENT(binder_txn_latency_free,
TP_PROTO(struct binder_transaction *t),
TP_ARGS(t),
@@ -106,6 +119,8 @@
__field(int, to_thread)
__field(unsigned int, code)
__field(unsigned int, flags)
+ __field(unsigned long, start_sec)
+ __field(unsigned long, start_nsec)
),
TP_fast_assign(
__entry->debug_id = t->debug_id;
@@ -115,11 +130,18 @@
__entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
__entry->code = t->code;
__entry->flags = t->flags;
- ),
- TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
+#ifdef CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING
+ __entry->start_sec = t->timestamp.tv_sec;
+ __entry->start_nsec = t->timestamp.tv_nsec / NSEC_PER_MSEC;
+#else
+ __entry->start_sec = 0;
+ __entry->start_nsec = 0;
+#endif
+ ),
+ TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x start %lu.%03ld",
__entry->debug_id, __entry->from_proc, __entry->from_thread,
__entry->to_proc, __entry->to_thread, __entry->code,
- __entry->flags)
+ __entry->flags, __entry->start_sec, __entry->start_nsec)
);

TRACE_EVENT(binder_transaction,
--
1.7.9.5