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

[Frankie Chang <Frankie.Chang@mediatek.com>]

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@mediatek.com> wrote:
> >
> > 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.
> 
> 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@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