[PATCH v5 3/3] binder: add transaction latency tracer
Frankie Chang
Frankie.Chang at mediatek.com
Wed Jul 22 23:01:53 EDT 2020
On Mon, 2020-07-20 at 11:56 -0700, Todd Kjos wrote:
> On Wed, Jun 10, 2020 at 5:34 AM Frankie Chang
> <Frankie.Chang at mediatek.com> wrote:
> >
> > From: "Frankie.Chang" <Frankie.Chang at 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.
>
> Could there be cases that 500ms is too long so 1s should be the
> threshold? Hard coded 2 seconds makes this less useful. How about
> making it configurable with a default of 2 sec?
>
Okay, it makes sense that making threshold configurable. We will do it.
> >
> > - 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 at 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"
>
> Any reason this can't be tristate?
>
It can be tristate, and we would change #ifdef to #if IS_ENABLED()
> > + 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
>
> If you make binder_latency_tracer a module, then we could include
> these fields unconditionally. Please add comments or give them better
> names so it is obvious what they are for.
>
We would add comments to explain what these used for.
> > + 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
>
> If you make binder_latency_tracer a module, then we could include
> these fields unconditionally. Please add comments or give them better
> names so it is obvious what they are for.
>
We would add comments to explain what these used for.
> > + 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;
>
> I still don't get why 2sec is magical. Should this threshold be configurable?
>
Okay, it makes sense that making threshold configurable. We will do it.
> > +
> > + 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);
>
> Why is the lock needed here?
>
We used it to protect @t->timestamp and @t->timeval, but it seems that
@t->timestamp and @t->timeval would not be changed in other place. So
we would remove it.
> > +}
> > +
> > +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
More information about the Linux-mediatek
mailing list