On Mon, 2020-09-07 at 16:09 +0200, Greg Kroah-Hartman wrote: > On Mon, Sep 07, 2020 at 09:51:15PM +0800, Frankie Chang wrote: > > 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.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 > > > > (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.ch...@mediatek.com> > > > > Acked-by: Todd Kjos <tk...@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.ker...@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 > > What exactly are you trying to measure such that you feel you need a > timeval structure? > Actually I'd like to record timestamp with standard time structure, so I used 'struct timeval' in the past patch. However it's deprecated, so I am looking for the alternatives.
Additionally, I have already looked some patches that replacing timeval with timespec64. I'll do the same way in next version patch. Many thanks, Frankie