[PATCH v8 3/3] binder: add transaction latency tracer
Frankie Chang
Frankie.Chang at mediatek.com
Mon Sep 7 09:51:15 EDT 2020
On Mon, 2020-09-07 at 14:25 +0200, Greg Kroah-Hartman wrote:
> On Mon, Sep 07, 2020 at 08:00:55PM +0800, Frankie Chang 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
> > (default 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 default
> > 2 seconds could be helpful to debug.
> > But this timeout threshold is configurable, to let
> > all users determine the more suitable threshold.
> >
> > - 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>
> > Acked-by: Todd Kjos <tkjos at google.com>
> > ---
> > drivers/android/Kconfig | 8 +++
> > drivers/android/Makefile | 1 +
> > drivers/android/binder.c | 6 ++
> > drivers/android/binder_internal.h | 13 ++++
> > drivers/android/binder_latency_tracer.c | 112 +++++++++++++++++++++++++++++++
> > drivers/android/binder_trace.h | 26 ++++++-
> > 6 files changed, 163 insertions(+), 3 deletions(-)
> > create mode 100644 drivers/android/binder_latency_tracer.c
> >
> > diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
> > index 53b22e2..8aadaf4 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
> > + tristate "Android Binder transaction tracking"
> > + help
> > + Used for track abnormal binder transaction which is over threshold,
> > + 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 0cab900..65ad38c 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -2674,6 +2674,7 @@ static void binder_transaction(struct binder_proc *proc,
> > return_error_line = __LINE__;
> > goto err_alloc_t_failed;
> > }
> > + trace_binder_txn_latency_alloc(t);
> > INIT_LIST_HEAD(&t->fd_fixups);
> > binder_stats_created(BINDER_STAT_TRANSACTION);
> > spin_lock_init(&t->lock);
> > @@ -5177,6 +5178,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) {
> > @@ -5818,4 +5820,8 @@ static int __init binder_init(void)
> > #define CREATE_TRACE_POINTS
> > #include "binder_trace.h"
> >
> > +EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_alloc);
> > +EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_info);
> > +EXPORT_TRACEPOINT_SYMBOL(binder_txn_latency_free);
> > +
> > MODULE_LICENSE("GPL v2");
> > diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> > index 872232f..309d1b10 100644
> > --- a/drivers/android/binder_internal.h
> > +++ b/drivers/android/binder_internal.h
> > @@ -15,6 +15,11 @@
> > #include <uapi/linux/android/binderfs.h>
> > #include "binder_alloc.h"
> >
> > +#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
> > +#include <uapi/linux/time_types.h>
> > +#include <linux/rtc.h>
> > +#endif
> > +
> > struct binder_context {
> > struct binder_node *binder_context_mgr_node;
> > struct mutex context_mgr_node_lock;
> > @@ -524,6 +529,14 @@ struct binder_transaction {
> > * during thread teardown
> > */
> > spinlock_t lock;
> > + /**
> > + * @timestamp and @tv are used to record the time
> > + * that the binder transaction startup
> > + */
> > +#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
> > + struct timespec64 timestamp;
> > + struct __kernel_old_timeval tv;
>
> As I stated in the 0/3 email, please use the correct in-kernel structure
> for this. That structure is _ONLY_ for old userspace api compatibility
> issues. Which is not the case here at all.
>
> thanks,
> greg k-h
Since it's not proper to use timeval & __kernel_old_timeval.
The remaining structure with tv_usec that I found is
__kernel_timex_timeval, but I'm not sure if this is proper one or not.
All I can see is in
https://lwn.net/ml/linux-kernel/20180705213604.18883-6-deepa.kernel@gmail.com/
I'm afraid of using wrong structure again.
Could you give me some advices about this?
Or is there another suitable way to replace timeval
Many thanks,
Frankie
More information about the Linux-mediatek
mailing list