On Wed, Jun 10, 2020 at 5:34 AM Frankie Chang <frankie.ch...@mediatek.com> wrote: > > From: "Frankie.Chang" <frankie.ch...@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? > > - 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.ch...@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? > + 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. > + 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. > + 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? > + > + 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? > +} > + > +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