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

[Frankie Chang]

On Wed, 2020-11-11 at 16:12 +0100, Greg Kroah-Hartman wrote:
> On Wed, Nov 11, 2020 at 11:03:06PM +0800, Frankie Chang wrote:
> > On Wed, 2020-11-11 at 08:34 +0100, Greg Kroah-Hartman wrote:
> > > > - 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.
> > > 
> > > Don't abuse the kernel information log for stuff that is just normal
> > > operations.  What is wrong with using the trace buffers here?  That's
> > > what they are designed for from what I can tell.
> > > 
> > As mentioned before, time limitation of recording is the reason why we
> > don't just use trace here.
> 
> What limitation?
> 
> > In some long time stability test, such as MTBF,
> 
> What is "MTBF"?
> 
Mean time between failures (MTBF) is the predicted elapsed time between
inherent failures of a mechanical or electronic system, during normal
system operation. 

And we use MTBF script to run long time stress test to
make sure our product stability is no problem.

> > the exception is caused by a series of transactions interaction.
> > Some abnormal transactions may be pending for a long time ago, they 
> > could not be recorded due to buffer limited.
> 
> How long of a time is this?  If they are pending, only when the timeout
> happens is the trace logged, right?
> 
> Again, please do not abuse the kernel log for this, that is not what it
> is for.
> 
Hmm..Do you mean that make timeout log print to trace buffer but not
kernel log? 

The reason We don't do this is that we need to enable these trace events
and enable trace everytimes before testing. But our testing script could
lead to device reboot, and then it continue testing after reboot. The
reboot would make these trace events disable, and we cannot get the
timeout log which happen after reboot.

> > > > +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.
> > > 
> > > Why is this a separate module?  Who will ever want this split out?
> > > 
> > The reason we split out a separate module is that we adopted the
> > previously discussed recommendations in PATCH v1.
> > 
> > This way all of this tracing code is in-kernel but outside of binder.c.
> 
> Putting it in a single file is fine, but what does this benifit doing it
> in a separate file?  Doesn't it waste more codespace this way?
> 
Yeah, but I think separate file may be more manageable.

> > > > +/*
> > > > + * The reason setting the binder_txn_latency_threshold to 2 sec
> > > > + * is that most of timeout abort is greater or equal to 2 sec.
> > > > + * Making it configurable to let all users determine which
> > > > + * threshold is more suitable.
> > > > + */
> > > > +static uint32_t binder_txn_latency_threshold = 2;
> > > > +module_param_named(threshold, binder_txn_latency_threshold,
> > > > +   uint, 0644);
> > > 
> > > Again, this isn't the 1990's, please do not add module parameters if at
> > > all possible.
> > > 
> > 
> > Is any recommended method here?
> > Because we refer to the method in binder.c, we don't know if this method
> > is not suitable.
> 
> Look at the individual binder instances.  That is what trace should be
> on/off for, not for all binder instances in the system at the same time.
> 
But our testing script is not for specific binder instances, it includes
several testing and tests for several processes.

So the reason we trace for all binder instances is that we cannot
predict which process would happen timeout transaction.

Many thanks
Frankie Chang

Re: [PATCH v14 1/3] binder: move structs from core file to header file

[Frankie Chang]

On Wed, 2020-11-11 at 16:12 +0100, Greg Kroah-Hartman wrote:
> On Wed, Nov 11, 2020 at 11:02:42PM +0800, Frankie Chang wrote:
> > From: "Frankie.Chang" 
> > 
> > Moving all structs to header file makes module more
> > extendable, and makes all these structs to be defined
> > in the same file.
> > 
> > Signed-off-by: Frankie.Chang 
> > Acked-by: Todd Kjos 
> > ---
> >  drivers/android/binder.c  |  406 
> > -
> >  drivers/android/binder_internal.h |  406 
> > +
> >  2 files changed, 406 insertions(+), 406 deletions(-)
> 
> This, and patch 2/3 was already accepted, right?
> 
> I can't do anything with them again :)
> 
Oh, okay :)

many thanks
Frankie Chang

[PATCH v14] binder: add transaction latency tracer

[Frankie Chang]

Change from v14:
  - prevent from directly print transaction info to kernel log.
  - give up doing the date math in the kernel.
  - track msec only instead of both sec and msec.
  - change EXPORT_TRACEPOINT_SYMBOL to EXPORT_TRACEPOINT_SYMBOL_GPL.

Change from v13:
  - modify patch subject.

Change from v12:
  - rebase.

Change from v11:
  - rebase.

Change from v10:
  - replace timespec64 with ktime_t.
  - fix build warning.

Change from v9:
  - rename timestamp to ts in binder_internal.h for conciseness.
  - change timeval to timespec64 in binder_internal.h

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 414 +++
 drivers/android/binder_latency_tracer.c | 108 ++
 drivers/android/binder_trace.h  |  46 +++
 6 files changed, 601 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

[PATCH v13] binder: add transaction latency tracer

[Frankie Chang]

Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 419 +++
 drivers/android/binder_latency_tracer.c | 107 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 608 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

[PATCH v12] binder: add transaction latency tracer

[Frankie Chang]

Change from v12:
  - rebase.

Change from v11:
  - rebase.

Change from v10:
  - replace timespec64 with ktime_t.
  - fix build warning.

Change from v9:
  - rename timestamp to ts in binder_internal.h for conciseness.
  - change timeval to timespec64 in binder_internal.h

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 419 +++
 drivers/android/binder_latency_tracer.c | 107 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 608 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

Re: binder: add transaction latency tracer

[Frankie Chang]

On Tue, 2020-11-10 at 08:53 +0100, Greg Kroah-Hartman wrote:
> On Tue, Nov 10, 2020 at 08:52:09AM +0100, Greg Kroah-Hartman wrote:
> > On Tue, Nov 10, 2020 at 03:33:00PM +0800, Frankie Chang wrote:
> > > On Mon, 2020-11-09 at 18:46 +0100, Greg Kroah-Hartman wrote:
> > > > On Fri, Oct 30, 2020 at 12:08:54AM +0800, Frankie Chang wrote:
> > > > > Change from v11:
> > > > >   - rebase.
> > > > 
> > > > This whole patch set is sent with DOS line-ends, which makes git really
> > > > unhappy when it tries to apply it, as rightfully, it doesn't know how to
> > > > convert things.
> > > > 
> > > Hmm.., actually I can use 'git apply' PATCH v11 from the message
> > > directly.
> > 
> > Ok, let me see if I can figure this out on my end, let me try using `b4`
> > on this to see if that helps...
> 
> Nope, there's still some merge conflicts here.  b4 fixed the line-end
> issues, but can you please rebase on top of my char-misc-next branch in
> the char.git tree on git.kernel.org and resend?  I think some changes by
> others are conflicting with this patchset somehow.
> 
Thanks for helping the line-end issues, 
I will rebase and verify locally then resend the patch set again.

Many thanks

Frankie Chang

Re: binder: add transaction latency tracer

[Frankie Chang]

On Mon, 2020-11-09 at 18:46 +0100, Greg Kroah-Hartman wrote:
> On Fri, Oct 30, 2020 at 12:08:54AM +0800, Frankie Chang wrote:
> > Change from v11:
> >   - rebase.
> 
> This whole patch set is sent with DOS line-ends, which makes git really
> unhappy when it tries to apply it, as rightfully, it doesn't know how to
> convert things.
> 
Hmm.., actually I can use 'git apply' PATCH v11 from the message
directly.

> Please resend this patch series as a plain-text patch series.  Perhaps
> using git send-email?  Something is converting these patches to an odd
> encoding which makes them not able to be applied.
> 
And I sent the patch set using git send-email. Hence, I am not sure what
happened when the patch set sent to others.

> Try sending them to yourself first, and seeing if you can apply them
> from the messages directly, and if so, then resend them.
> 
But I will still verify locally and resend again.

thanks

Frankie Chang

binder: add transaction latency tracer

[Frankie Chang]

Change from v11:
  - rebase.

Change from v10:
  - replace timespec64 with ktime_t.
  - fix build warning.

Change from v9:
  - rename timestamp to ts in binder_internal.h for conciseness.
  - change timeval to timespec64 in binder_internal.h

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 419 +++
 drivers/android/binder_latency_tracer.c | 107 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 608 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

[PATCH v10 3/3] binder: add transaction latency tracer

[Frankie Chang]

Change from v10:
  - replace timespec64 with ktime_t.
  - fix build warning.

Change from v9:
  - rename timestamp to ts in binder_internal.h for conciseness.
  - change timeval to timespec64 in binder_internal.h

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 418 +++
 drivers/android/binder_latency_tracer.c | 107 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 607 insertions(+), 406 deletions(-)  create mode 100644 
drivers/android/binder_latency_tracer.c

[PATCH v9] binder: transaction latency tracking for user build

[Frankie Chang]

Change from v9:
  - rename timestamp to ts in binder_internal.h for conciseness.
  - change 'struct timeval' to 'struct timespec64' in binder_internal.h.

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 418 +++
 drivers/android/binder_latency_tracer.c | 108 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 608 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

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

[Frankie Chang]

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" 
> > > > 
> > > > 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 
> > > > Acked-by: Todd Kjos 
> > > > ---
> > > >  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/dr

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

[Frankie Chang]

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" 
> > 
> > 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 
> > Acked-by: Todd Kjos 
> > ---
> >  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)
> >  #defi

[PATCH v8] binder: transaction latency tracking for user build

[Frankie Chang]

Change from v8:
  - change rtc_time_to_tm to rtc_time64_to_tm.
  - change timeval to __kernel_old_timeval due to 

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=c766d1472c70d25ad475cf56042af1652e792b23
  - export tracepoint symbol for binder_txn_latency_* which 
binder_transaction_latency_tracer to be ko needed.

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.


Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 430 ++--
 drivers/android/binder_internal.h   | 418 +++
 drivers/android/binder_latency_tracer.c | 112 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 612 insertions(+), 406 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

Re: [PATCH v7] binder: transaction latency tracking for user build

[Frankie Chang]

On Thu, 2020-09-03 at 18:21 +0200, Greg Kroah-Hartman wrote:
> On Tue, Aug 04, 2020 at 09:59:09PM +0800, Frankie Chang wrote:
> > 
> > Frankie.Chang (3):
> >   binder: move structs from core file to header file
> >   binder: add trace at free transaction.
> >   binder: add transaction latency tracer
> > 
> >  drivers/android/Kconfig |8 +
> >  drivers/android/Makefile|1 +
> >  drivers/android/binder.c|  425 
> > ++-
> >  drivers/android/binder_internal.h   |  417 
> > ++
> >  drivers/android/binder_latency_tracer.c |  112 
> >  drivers/android/binder_trace.h  |   49 
> >  6 files changed, 607 insertions(+), 405 deletions(-)  create mode 100644 
> > drivers/android/binder_latency_tracer.c
> 
> This series blows up the build into lots of tiny pieces, how was it
> tested?
> 

I am sorry that I had built pass.on the too older kernel, and some of
api had been deprecated.
I have fixed these errors in local, and I add the
EXPORT_TRACEPOINT_SYMBOL for binder_latency_tracer to be ko needed.

Do I need to push a patch V8 or I provide the fixed code here ?

~/mtk_soc_new$ cat b.log | grep binder
  CC  drivers/android/binderfs.o
  CC  drivers/android/binder.o
  CC [M]  drivers/android/binder_latency_tracer.o
  LD [M]  drivers/android/binder_latency_tracer.ko

~/mtk_soc_new$ tail -n 10 b.log
make[1]: Leaving directory `/proj/mtk16184/mtk_soc_new/kernel/mediatek'
make ARCH=arm64
CROSS_COMPILE=/proj/mtk16184/mtk_soc_new/prebuilt/toolchain/aarch64/usr/bin/aarch64-poky-linux/aarch64-poky-linux-
 O=/proj/mtk16184/mtk_soc_new/out -C kernel/mediatek dtbs
make[1]: Entering directory `/proj/mtk16184/mtk_soc_new/kernel/mediatek'
make[2]: Entering directory `/proj/mtk16184/mtk_soc_new/out'
arch/arm64/Makefile:26: ld does not support --fix-cortex-a53-843419;
kernel may be susceptible to erratum
arch/arm64/Makefile:34: LSE atomics not supported by binutils
make[2]: Leaving directory `/proj/mtk16184/mtk_soc_new/out'
make[1]: Leaving directory `/proj/mtk16184/mtk_soc_new/kernel/mediatek'
cat /proj/mtk16184/mtk_soc_new/out/arch/arm64/boot/Image.gz 
/proj/mtk16184/mtk_soc_new/out/arch/arm64/boot/dts/mediatek/mt6779-evb.dtb > 
/proj/mtk16184/mtk_soc_new/out/arch/arm64/boot/Image.gz-dtb
/proj/mtk16184/mtk_soc_new/prebuilt/bootable/mkbootimg
--kernel /proj/mtk16184/mtk_soc_new/out/arch/arm64/boot/Image.gz-dtb
--ramdisk /proj/mtk16184/mtk_soc_new/prebuilt/bootable/6779_loader/ramdisk.img 
--base 0x4000 --ramdisk_offset 0x0400 --kernel_offset 0x0008 
--cmdline bootopt=64S3,32N2,64N2 --output 
/proj/mtk16184/mtk_soc_new/prebuilt/bootable/6779_loader/boot.img


> Here's my error logs:
> 
> In file included from drivers/android/binderfs.c:37:
> drivers/android/binder_internal.h:537:17: error: field ‘tv’ has incomplete 
> type
>   537 |  struct timeval tv;
>   | ^~
> In file included from drivers/android/binder_trace.h:12,
>  from drivers/android/binder_alloc.c:27:
> drivers/android/binder_trace.h: In function ‘trace_binder_txn_latency_alloc’:
> drivers/android/binder_trace.h:100:13: error: ‘e’ undeclared (first use in 
> this function)
>   100 |  TP_ARGS(t, e)
>   | ^
> ./include/linux/tracepoint.h:191:33: note: in definition of macro ‘__DO_TRACE’
>   191 | ((void(*)(proto))(it_func))(args); \
>   | ^~~~
> ./include/linux/tracepoint.h:236:5: note: in expansion of macro ‘TP_ARGS’
>   236 | TP_ARGS(data_args),   \
>   | ^~~
> ./include/linux/tracepoint.h:375:2: note: in expansion of macro 
> ‘__DECLARE_TRACE’
>   375 |  __DECLARE_TRACE(name, PARAMS(proto), PARAMS(args),  \
>   |  ^~~
> ./include/linux/tracepoint.h:378:4: note: in expansion of macro ‘PARAMS’
>   378 |PARAMS(__data, args))
>   |^~
> drivers/android/binder_trace.h:98:1: note: in expansion of macro 
> ‘DECLARE_TRACE’
>98 | DECLARE_TRACE(binder_txn_latency_alloc,
>   | ^
> drivers/android/binder_trace.h:100:2: note: in expansion of macro ‘TP_ARGS’
>   100 |  TP_ARGS(t, e)
>   |  ^~~
> drivers/android/binder_trace.h:100:13: note: each undeclared identifier is 
> reported only once for each function it appears in
>   100 |  TP_ARGS(t, e)
>   | ^
> ./include/linux/tracepoint.h:191:33: note: in definition of macro ‘__DO_TRACE’
>   191 | ((void(*)(proto))(it_func))(args); \
>   | ^~~~
> ./include/linux/tracepoint.h:236:5: note: in expansion of macro ‘TP_ARGS’
>   236 | TP_ARGS(data_args),   \
>   | ^~~
> ./inc

[PATCH v7 3/3] binder: add transaction latency tracer

[Frankie Chang]

From: "Frankie.Chang" 

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 
---
 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 |  112 +++
 drivers/android/binder_trace.h  |   26 ++-
 6 files changed, 159 insertions(+), 3 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
index 6fdf2ab..91fff1e 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 1bfadc2..22f7cc6 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -2671,6 +2671,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);
@@ -5159,6 +5160,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 5b65413..596db00 100644
--- a/drivers/android/binder_internal.h
+++ b/drivers/android/binder_internal.h
@@ -13,6 +13,11 @@
 #include 
 #include "binder_alloc.h"
 
+#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
+#include 
+#include 
+#endif
+
 struct binder_context {
struct binder_node *binder_context_mgr_node;
struct mutex context_mgr_node_lock;
@@ -521,6 +526,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 timeval tv;
+#endif
 };
 
 /**
diff --git a/drivers/android/binder_latency_tracer.c 
b/drivers/android/binder_latency_tracer.c
new file mode 100644
index 000..61ae75f
--- /dev/null
+++ b/drivers/android/binder_latency_tracer.c
@@ -0,0 +1,112 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2019 MediaTek Inc.
+ */
+
+#include 
+#include 
+#inclu

[PATCH v7 2/3] binder: add trace at free transaction.

[Frankie Chang]

From: "Frankie.Chang" 

Since the original trace_binder_transaction_received cannot
precisely present the real finished time of transaction, adding a
trace_binder_txn_latency_free at the point of free transaction
may be more close to it.

Signed-off-by: Frankie.Chang 
---
 drivers/android/binder.c   |   18 ++
 drivers/android/binder_trace.h |   29 +
 2 files changed, 47 insertions(+)

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index 2df146f..1bfadc2 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -1508,6 +1508,20 @@ static void binder_free_txn_fixups(struct 
binder_transaction *t)
}
 }
 
+static void binder_txn_latency_free(struct binder_transaction *t)
+{
+   int from_proc, from_thread, to_proc, to_thread;
+
+   spin_lock(&t->lock);
+   from_proc = t->from ? t->from->proc->pid : 0;
+   from_thread = t->from ? t->from->pid : 0;
+   to_proc = t->to_proc ? t->to_proc->pid : 0;
+   to_thread = t->to_thread ? t->to_thread->pid : 0;
+   spin_unlock(&t->lock);
+
+   trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc, 
to_thread);
+}
+
 static void binder_free_transaction(struct binder_transaction *t)
 {
struct binder_proc *target_proc = t->to_proc;
@@ -1518,6 +1532,8 @@ static void binder_free_transaction(struct 
binder_transaction *t)
t->buffer->transaction = NULL;
binder_inner_proc_unlock(target_proc);
}
+   if (trace_binder_txn_latency_free_enabled())
+   binder_txn_latency_free(t);
/*
 * If the transaction has no target_proc, then
 * t->buffer->transaction has already been cleared.
@@ -3093,6 +3109,8 @@ static void binder_transaction(struct binder_proc *proc,
kfree(tcomplete);
binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
 err_alloc_tcomplete_failed:
+   if (trace_binder_txn_latency_free_enabled())
+   binder_txn_latency_free(t);
kfree(t);
binder_stats_deleted(BINDER_STAT_TRANSACTION);
 err_alloc_t_failed:
diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
index 6731c3c..eb2c53c 100644
--- a/drivers/android/binder_trace.h
+++ b/drivers/android/binder_trace.h
@@ -95,6 +95,35 @@
  __entry->thread_todo)
 );
 
+TRACE_EVENT(binder_txn_latency_free,
+   TP_PROTO(struct binder_transaction *t
+int from_proc, int from_thread
+int to_proc, int to_thread),
+   TP_ARGS(t, from_proc, from_thread, to_proc, to_thread),
+   TP_STRUCT__entry(
+   __field(int, debug_id)
+   __field(int, from_proc)
+   __field(int, from_thread)
+   __field(int, to_proc)
+   __field(int, to_thread)
+   __field(unsigned int, code)
+   __field(unsigned int, flags)
+   ),
+   TP_fast_assign(
+   __entry->debug_id = t->debug_id;
+   __entry->from_proc = from_proc;
+   __entry->from_thread = from_thread;
+   __entry->to_proc = to_proc;
+   __entry->to_thread = to_thread;
+   __entry->code = t->code;
+   __entry->flags = t->flags;
+   ),
+   TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
+ __entry->debug_id, __entry->from_proc, __entry->from_thread,
+ __entry->to_proc, __entry->to_thread, __entry->code,
+ __entry->flags)
+);
+
 TRACE_EVENT(binder_transaction,
TP_PROTO(bool reply, struct binder_transaction *t,
 struct binder_node *target_node),
-- 
1.7.9.5

[PATCH v7] binder: transaction latency tracking for user build

[Frankie Chang]

Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |8 +
 drivers/android/Makefile|1 +
 drivers/android/binder.c|  425 ++-
 drivers/android/binder_internal.h   |  417 ++
 drivers/android/binder_latency_tracer.c |  112 
 drivers/android/binder_trace.h  |   49 
 6 files changed, 607 insertions(+), 405 deletions(-)  create mode 100644 
drivers/android/binder_latency_tracer.c

Change from v7:
  - Use the passed-in values instead of accessing via t->from/to_proc/to_thread
for trace_binder_txn_latency_free, when 
trace_binder_txn_latency_free_enable() return true.
  - make a helper function to do the above.

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.

[PATCH v7 1/3] binder: move structs from core file to header file

[Frankie Chang]

From: "Frankie.Chang" 

Moving all structs to header file makes module more
extendable, and makes all these structs to be defined
in the same file.

Signed-off-by: Frankie.Chang 
---
 drivers/android/binder.c  |  405 -
 drivers/android/binder_internal.h |  404 
 2 files changed, 404 insertions(+), 405 deletions(-)

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index a6b2082..2df146f 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -72,7 +72,6 @@
 
 #include 
 
-#include "binder_alloc.h"
 #include "binder_internal.h"
 #include "binder_trace.h"
 
@@ -160,24 +159,6 @@ static int binder_set_stop_on_user_error(const char *val,
 #define to_binder_fd_array_object(hdr) \
container_of(hdr, struct binder_fd_array_object, hdr)
 
-enum binder_stat_types {
-   BINDER_STAT_PROC,
-   BINDER_STAT_THREAD,
-   BINDER_STAT_NODE,
-   BINDER_STAT_REF,
-   BINDER_STAT_DEATH,
-   BINDER_STAT_TRANSACTION,
-   BINDER_STAT_TRANSACTION_COMPLETE,
-   BINDER_STAT_COUNT
-};
-
-struct binder_stats {
-   atomic_t br[_IOC_NR(BR_FAILED_REPLY) + 1];
-   atomic_t bc[_IOC_NR(BC_REPLY_SG) + 1];
-   atomic_t obj_created[BINDER_STAT_COUNT];
-   atomic_t obj_deleted[BINDER_STAT_COUNT];
-};
-
 static struct binder_stats binder_stats;
 
 static inline void binder_stats_deleted(enum binder_stat_types type)
@@ -213,278 +194,11 @@ static struct binder_transaction_log_entry 
*binder_transaction_log_add(
return e;
 }
 
-/**
- * struct binder_work - work enqueued on a worklist
- * @entry: node enqueued on list
- * @type:  type of work to be performed
- *
- * There are separate work lists for proc, thread, and node (async).
- */
-struct binder_work {
-   struct list_head entry;
-
-   enum {
-   BINDER_WORK_TRANSACTION = 1,
-   BINDER_WORK_TRANSACTION_COMPLETE,
-   BINDER_WORK_RETURN_ERROR,
-   BINDER_WORK_NODE,
-   BINDER_WORK_DEAD_BINDER,
-   BINDER_WORK_DEAD_BINDER_AND_CLEAR,
-   BINDER_WORK_CLEAR_DEATH_NOTIFICATION,
-   } type;
-};
-
-struct binder_error {
-   struct binder_work work;
-   uint32_t cmd;
-};
-
-/**
- * struct binder_node - binder node bookkeeping
- * @debug_id: unique ID for debugging
- *(invariant after initialized)
- * @lock: lock for node fields
- * @work: worklist element for node work
- *(protected by @proc->inner_lock)
- * @rb_node:  element for proc->nodes tree
- *(protected by @proc->inner_lock)
- * @dead_node:element for binder_dead_nodes list
- *(protected by binder_dead_nodes_lock)
- * @proc: binder_proc that owns this node
- *(invariant after initialized)
- * @refs: list of references on this node
- *(protected by @lock)
- * @internal_strong_refs: used to take strong references when
- *initiating a transaction
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @local_weak_refs:  weak user refs from local process
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @local_strong_refs:strong user refs from local process
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @tmp_refs: temporary kernel refs
- *(protected by @proc->inner_lock while @proc
- *is valid, and by binder_dead_nodes_lock
- *if @proc is NULL. During inc/dec and node release
- *it is also protected by @lock to provide safety
- *as the node dies and @proc becomes NULL)
- * @ptr:  userspace pointer for node
- *(invariant, no lock needed)
- * @cookie:   userspace cookie for node
- *(invariant, no lock needed)
- * @has_strong_ref:   userspace notified of strong ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @pending_strong_ref:   userspace has acked notification of strong ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @has_weak_ref: userspace notified of weak ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @pending_weak_ref: userspace has acked notification of weak ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * 

Re: [PATCH v6 2/3] binder: add trace at free transaction.

[Frankie Chang]

On Mon, 2020-08-03 at 08:12 -0700, Todd Kjos wrote:
> On Sun, Aug 2, 2020 at 8:11 PM Frankie Chang  
> wrote:
> >
> > On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> > > On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
> > >  wrote:
> > > >
> > > > From: "Frankie.Chang" 
> > > >
> > > > Since the original trace_binder_transaction_received cannot
> > > > precisely present the real finished time of transaction, adding a
> > > > trace_binder_txn_latency_free at the point of free transaction
> > > > may be more close to it.
> > > >
> > > > Signed-off-by: Frankie.Chang 
> > > > ---
> > > >  drivers/android/binder.c   |6 ++
> > > >  drivers/android/binder_trace.h |   27 +++
> > > >  2 files changed, 33 insertions(+)
> > > >
> > > > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > > > index 2df146f..1e6fc40 100644
> > > > --- a/drivers/android/binder.c
> > > > +++ b/drivers/android/binder.c
> > > > @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct 
> > > > binder_transaction *t)
> > > >  * If the transaction has no target_proc, then
> > > >  * t->buffer->transaction has already been cleared.
> > > >  */
> > > > +   spin_lock(&t->lock);
> > > > +   trace_binder_txn_latency_free(t);
> > > > +   spin_unlock(&t->lock);
> > >
> > > Hmm. I don't prefer taking the lock just to call a trace. It doesn't
> > > make clear why the lock has to be taken. I'd prefer something like:
> > >
> > > if (trace_binder_txn_latency_free_enabled()) {
> > c
> > > }
> > >
> > > And then the trace would use the passed-in values instead of accessing
> > > via t->to_proc/to_thread.
> > >
> > Then we still add lock protection in the hook function, when trace is
> > disable ?
> 
> I don't understand... in the example I gave, the trace doesn't get
> called if disabled. What do you mean to "add lock protection when the
> trace is disabled()"?
> 
> >
> > Or we also pass these to hook function, no matter the trace is enable or
> 
> What do you mean by "hook" function? If something has attached to the
> trace, then xxx_enabled() will return true.
> 
I'm sorry for that I misunderstand this XXX_enabled(). 

> > not.I think this way is more clear that the lock protects @from,
> > @to_proc and @to_thread.Then, there is no need to add the lock in hook
> > function.
> 
> Why is it clearer (other than the fact that I missed including t->from
> under the lock)?
> 
I think your example is clear enough.

> >
> > int from_proc, from_thread, to_proc, to_thread;
> >
> > spin_lock(&t->lock);
> > from_proc = t->from ? t->from->proc->pid : 0;
> > from_thread = t->from ? t->from->pid :0;
> > to_proc = t->to_proc ? t->to_proc->pid : 0;
> > to_thread = t->to_thread ? t->to_thread->pid : 0;
> > spin_unlock(&t->lock);
> > trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc,
> > to_pid);
> 
> The main feedback is I'd like to see the fields dereferenced in the
> same context as the lock acquisition instead of acquiring the lock and
> calling the trace function, so this code would be fine. There will be
> very little contention for t->lock so using xxx_enabled() is optional.
> 
> Since trace_binder_txn_latency_free() is called twice,  it would make
> sense to have a helper function to do the above.
> 
Okay, I will make a helper function to do this in next version patch.
Very thanks for your help for this.

> >
> > > > binder_free_txn_fixups(t);
> > > > kfree(t);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > > @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc 
> > > > *proc,
> > > > kfree(tcomplete);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> > > >  err_alloc_tcomplete_failed:
> > > > +   spin_lock(&t->lock);
> > > > +   trace_binder_txn_latency_free(t);
> > > > +   spin_unlock(&t->lock);
> > > > kfree(t);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > >

Re: [PATCH v6 2/3] binder: add trace at free transaction.

[Frankie Chang]

On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
>  wrote:
> >
> > From: "Frankie.Chang" 
> >
> > Since the original trace_binder_transaction_received cannot
> > precisely present the real finished time of transaction, adding a
> > trace_binder_txn_latency_free at the point of free transaction
> > may be more close to it.
> >
> > Signed-off-by: Frankie.Chang 
> > ---
> >  drivers/android/binder.c   |6 ++
> >  drivers/android/binder_trace.h |   27 +++
> >  2 files changed, 33 insertions(+)
> >
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 2df146f..1e6fc40 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct 
> > binder_transaction *t)
> >  * If the transaction has no target_proc, then
> >  * t->buffer->transaction has already been cleared.
> >  */
> > +   spin_lock(&t->lock);
> > +   trace_binder_txn_latency_free(t);
> > +   spin_unlock(&t->lock);
> 
> Hmm. I don't prefer taking the lock just to call a trace. It doesn't
> make clear why the lock has to be taken. I'd prefer something like:
> 
> if (trace_binder_txn_latency_free_enabled()) {
c
> }
> 
> And then the trace would use the passed-in values instead of accessing
> via t->to_proc/to_thread.
> 
Then we still add lock protection in the hook function, when trace is
disable ?

Or we also pass these to hook function, no matter the trace is enable or
not.I think this way is more clear that the lock protects @from,
@to_proc and @to_thread.Then, there is no need to add the lock in hook
function.

int from_proc, from_thread, to_proc, to_thread;
 
spin_lock(&t->lock);
from_proc = t->from ? t->from->proc->pid : 0;
from_thread = t->from ? t->from->pid :0;
to_proc = t->to_proc ? t->to_proc->pid : 0;
to_thread = t->to_thread ? t->to_thread->pid : 0;
spin_unlock(&t->lock);
trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc,
to_pid);

> > binder_free_txn_fixups(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc 
> > *proc,
> > kfree(tcomplete);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> >  err_alloc_tcomplete_failed:
> > +   spin_lock(&t->lock);
> > +   trace_binder_txn_latency_free(t);
> > +   spin_unlock(&t->lock);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> >  err_alloc_t_failed:
> > diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
> > index 6731c3c..8ac87d1 100644
> > --- a/drivers/android/binder_trace.h
> > +++ b/drivers/android/binder_trace.h
> > @@ -95,6 +95,33 @@
> >   __entry->thread_todo)
> >  );
> >
> > +TRACE_EVENT(binder_txn_latency_free,
> > +   TP_PROTO(struct binder_transaction *t),
> > +   TP_ARGS(t),
> > +   TP_STRUCT__entry(
> > +   __field(int, debug_id)
> > +   __field(int, from_proc)
> > +   __field(int, from_thread)
> > +   __field(int, to_proc)
> > +   __field(int, to_thread)
> > +   __field(unsigned int, code)
> > +   __field(unsigned int, flags)
> > +   ),
> > +   TP_fast_assign(
> > +   __entry->debug_id = t->debug_id;
> > +   __entry->from_proc = t->from ? t->from->proc->pid : 0;
> > +   __entry->from_thread = t->from ? t->from->pid : 0;
> > +   __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
> > +   __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",
> > + __entry->debug_id, __entry->from_proc, 
> > __entry->from_thread,
> > + __entry->to_proc, __entry->to_thread, __entry->code,
> > + __entry->flags)
> > +);
> > +
> >  TRACE_EVENT(binder_transaction,
> > TP_PROTO(bool reply, struct binder_transaction *t,
> >  struct binder_node *target_node),
> > --
> > 1.7.9.5

[PATCH v6 3/3] binder: add transaction latency tracer

[Frankie Chang]

From: "Frankie.Chang" 

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 
---
 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 |  112 +++
 drivers/android/binder_trace.h  |   26 ++-
 6 files changed, 159 insertions(+), 3 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
index 6fdf2ab..91fff1e 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 1e6fc40..0956403 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -2658,6 +2658,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);
@@ -5147,6 +5148,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 5b65413..596db00 100644
--- a/drivers/android/binder_internal.h
+++ b/drivers/android/binder_internal.h
@@ -13,6 +13,11 @@
 #include 
 #include "binder_alloc.h"
 
+#if IS_ENABLED(CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING)
+#include 
+#include 
+#endif
+
 struct binder_context {
struct binder_node *binder_context_mgr_node;
struct mutex context_mgr_node_lock;
@@ -521,6 +526,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 timeval tv;
+#endif
 };
 
 /**
diff --git a/drivers/android/binder_latency_tracer.c 
b/drivers/android/binder_latency_tracer.c
new file mode 100644
index 000..b339ae1
--- /dev/null
+++ b/drivers/android/binder_latency_tracer.c
@@ -0,0 +1,112 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2019 MediaTek Inc.
+ */
+
+#include 
+#include 
+#inclu

[PATCH v6] binder: transaction latency tracking for user build

[Frankie Chang]

Change from v6:
  - change CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING type from bool to tristate
  - add comments to @timestamp and @tv under struct binder_transaction
  - make binder_txn_latency threshold configurable
  - enhance lock protection

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.

[PATCH v6 2/3] binder: add trace at free transaction.

[Frankie Chang]

From: "Frankie.Chang" 

Since the original trace_binder_transaction_received cannot
precisely present the real finished time of transaction, adding a
trace_binder_txn_latency_free at the point of free transaction
may be more close to it.

Signed-off-by: Frankie.Chang 
---
 drivers/android/binder.c   |6 ++
 drivers/android/binder_trace.h |   27 +++
 2 files changed, 33 insertions(+)

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index 2df146f..1e6fc40 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct 
binder_transaction *t)
 * If the transaction has no target_proc, then
 * t->buffer->transaction has already been cleared.
 */
+   spin_lock(&t->lock);
+   trace_binder_txn_latency_free(t);
+   spin_unlock(&t->lock);
binder_free_txn_fixups(t);
kfree(t);
binder_stats_deleted(BINDER_STAT_TRANSACTION);
@@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc *proc,
kfree(tcomplete);
binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
 err_alloc_tcomplete_failed:
+   spin_lock(&t->lock);
+   trace_binder_txn_latency_free(t);
+   spin_unlock(&t->lock);
kfree(t);
binder_stats_deleted(BINDER_STAT_TRANSACTION);
 err_alloc_t_failed:
diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
index 6731c3c..8ac87d1 100644
--- a/drivers/android/binder_trace.h
+++ b/drivers/android/binder_trace.h
@@ -95,6 +95,33 @@
  __entry->thread_todo)
 );
 
+TRACE_EVENT(binder_txn_latency_free,
+   TP_PROTO(struct binder_transaction *t),
+   TP_ARGS(t),
+   TP_STRUCT__entry(
+   __field(int, debug_id)
+   __field(int, from_proc)
+   __field(int, from_thread)
+   __field(int, to_proc)
+   __field(int, to_thread)
+   __field(unsigned int, code)
+   __field(unsigned int, flags)
+   ),
+   TP_fast_assign(
+   __entry->debug_id = t->debug_id;
+   __entry->from_proc = t->from ? t->from->proc->pid : 0;
+   __entry->from_thread = t->from ? t->from->pid : 0;
+   __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
+   __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",
+ __entry->debug_id, __entry->from_proc, __entry->from_thread,
+ __entry->to_proc, __entry->to_thread, __entry->code,
+ __entry->flags)
+);
+
 TRACE_EVENT(binder_transaction,
TP_PROTO(bool reply, struct binder_transaction *t,
 struct binder_node *target_node),
-- 
1.7.9.5

[PATCH v6 1/3] binder: move structs from core file to header file

[Frankie Chang]

From: "Frankie.Chang" 

Moving all structs to header file makes module more
extendable, and makes all these structs to be defined
in the same file.

Signed-off-by: Frankie.Chang 
---
 drivers/android/binder.c  |  405 -
 drivers/android/binder_internal.h |  404 
 2 files changed, 404 insertions(+), 405 deletions(-)

diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index a6b2082..2df146f 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -72,7 +72,6 @@
 
 #include 
 
-#include "binder_alloc.h"
 #include "binder_internal.h"
 #include "binder_trace.h"
 
@@ -160,24 +159,6 @@ static int binder_set_stop_on_user_error(const char *val,
 #define to_binder_fd_array_object(hdr) \
container_of(hdr, struct binder_fd_array_object, hdr)
 
-enum binder_stat_types {
-   BINDER_STAT_PROC,
-   BINDER_STAT_THREAD,
-   BINDER_STAT_NODE,
-   BINDER_STAT_REF,
-   BINDER_STAT_DEATH,
-   BINDER_STAT_TRANSACTION,
-   BINDER_STAT_TRANSACTION_COMPLETE,
-   BINDER_STAT_COUNT
-};
-
-struct binder_stats {
-   atomic_t br[_IOC_NR(BR_FAILED_REPLY) + 1];
-   atomic_t bc[_IOC_NR(BC_REPLY_SG) + 1];
-   atomic_t obj_created[BINDER_STAT_COUNT];
-   atomic_t obj_deleted[BINDER_STAT_COUNT];
-};
-
 static struct binder_stats binder_stats;
 
 static inline void binder_stats_deleted(enum binder_stat_types type)
@@ -213,278 +194,11 @@ static struct binder_transaction_log_entry 
*binder_transaction_log_add(
return e;
 }
 
-/**
- * struct binder_work - work enqueued on a worklist
- * @entry: node enqueued on list
- * @type:  type of work to be performed
- *
- * There are separate work lists for proc, thread, and node (async).
- */
-struct binder_work {
-   struct list_head entry;
-
-   enum {
-   BINDER_WORK_TRANSACTION = 1,
-   BINDER_WORK_TRANSACTION_COMPLETE,
-   BINDER_WORK_RETURN_ERROR,
-   BINDER_WORK_NODE,
-   BINDER_WORK_DEAD_BINDER,
-   BINDER_WORK_DEAD_BINDER_AND_CLEAR,
-   BINDER_WORK_CLEAR_DEATH_NOTIFICATION,
-   } type;
-};
-
-struct binder_error {
-   struct binder_work work;
-   uint32_t cmd;
-};
-
-/**
- * struct binder_node - binder node bookkeeping
- * @debug_id: unique ID for debugging
- *(invariant after initialized)
- * @lock: lock for node fields
- * @work: worklist element for node work
- *(protected by @proc->inner_lock)
- * @rb_node:  element for proc->nodes tree
- *(protected by @proc->inner_lock)
- * @dead_node:element for binder_dead_nodes list
- *(protected by binder_dead_nodes_lock)
- * @proc: binder_proc that owns this node
- *(invariant after initialized)
- * @refs: list of references on this node
- *(protected by @lock)
- * @internal_strong_refs: used to take strong references when
- *initiating a transaction
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @local_weak_refs:  weak user refs from local process
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @local_strong_refs:strong user refs from local process
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @tmp_refs: temporary kernel refs
- *(protected by @proc->inner_lock while @proc
- *is valid, and by binder_dead_nodes_lock
- *if @proc is NULL. During inc/dec and node release
- *it is also protected by @lock to provide safety
- *as the node dies and @proc becomes NULL)
- * @ptr:  userspace pointer for node
- *(invariant, no lock needed)
- * @cookie:   userspace cookie for node
- *(invariant, no lock needed)
- * @has_strong_ref:   userspace notified of strong ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @pending_strong_ref:   userspace has acked notification of strong ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @has_weak_ref: userspace notified of weak ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * @pending_weak_ref: userspace has acked notification of weak ref
- *(protected by @proc->inner_lock if @proc
- *and by @lock)
- * 

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

[Frankie Chang]

On Mon, 2020-07-20 at 11:56 -0700, Todd Kjos wrote:
> On Wed, Jun 10, 2020 at 5:34 AM Frankie Chang
>  wrote:
> >
> > From: "Frankie.Chang" 
> >
> > 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 
> > ---
> >  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,
&

Re: [PATCH v5 2/3] binder: add trace at free transaction.

[Frankie Chang]

On Mon, 2020-07-20 at 11:23 -0700, Todd Kjos wrote:
> On Wed, Jun 10, 2020 at 5:24 AM Frankie Chang
>  wrote:
> >
> > From: "Frankie.Chang" 
> >
> > Since the original trace_binder_transaction_received cannot
> > precisely present the real finished time of transaction, adding a
> > trace_binder_txn_latency_free at the point of free transaction
> > may be more close to it.
> >
> > Signed-off-by: Frankie.Chang 
> > ---
> >  drivers/android/binder.c   |2 ++
> >  drivers/android/binder_trace.h |   27 +++
> >  2 files changed, 29 insertions(+)
> >
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 1592396..5ec9af8 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -1523,6 +1523,7 @@ static void binder_free_transaction(struct 
> > binder_transaction *t)
> >  * If the transaction has no target_proc, then
> >  * t->buffer->transaction has already been cleared.
> >  */
> > +   trace_binder_txn_latency_free(t);
> > binder_free_txn_fixups(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > @@ -3094,6 +3095,7 @@ static void binder_transaction(struct binder_proc 
> > *proc,
> > kfree(tcomplete);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> >  err_alloc_tcomplete_failed:
> > +   trace_binder_txn_latency_free(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> >  err_alloc_t_failed:
> > diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
> > index 6731c3c..8ac87d1 100644
> > --- a/drivers/android/binder_trace.h
> > +++ b/drivers/android/binder_trace.h
> > @@ -95,6 +95,33 @@
> >   __entry->thread_todo)
> >  );
> >
> > +TRACE_EVENT(binder_txn_latency_free,
> > +   TP_PROTO(struct binder_transaction *t),
> > +   TP_ARGS(t),
> > +   TP_STRUCT__entry(
> > +   __field(int, debug_id)
> > +   __field(int, from_proc)
> > +   __field(int, from_thread)
> > +   __field(int, to_proc)
> > +   __field(int, to_thread)
> > +   __field(unsigned int, code)
> > +   __field(unsigned int, flags)
> > +   ),
> > +   TP_fast_assign(
> > +   __entry->debug_id = t->debug_id;
> > +   __entry->from_proc = t->from ? t->from->proc->pid : 0;
> > +   __entry->from_thread = t->from ? t->from->pid : 0;
> > +   __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
> > +   __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
> 
> t->to_proc and t->to_thread are not safe to dereference without
> holding t->lock. If the target process dies, these fields can be set
> to NULL
> 
Thanks for remind. I will add lock protection for these t->to_proc &
t->to_thread in v7.

> > +   __entry->code = t->code;
> > +   __entry->flags = t->flags;
> > +   ),
> > +   TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
> > + __entry->debug_id, __entry->from_proc, 
> > __entry->from_thread,
> > + __entry->to_proc, __entry->to_thread, __entry->code,
> > + __entry->flags)
> > +);
> > +
> >  TRACE_EVENT(binder_transaction,
> > TP_PROTO(bool reply, struct binder_transaction *t,
> >  struct binder_node *target_node),
> > --
> > 1.7.9.5

Re: [PATCH v5] binder: transaction latency tracking for user build

[Frankie Chang]

Hi Greg, Todd and all

Gentle ping for this patch set

Thanks

On Thu, 2020-07-02 at 21:25 +0800, Frankie Chang wrote:
> Hi Greg, Todd and all
> 
> Gentle remind of this patch set
> 
> Thanks.
> Frankie
> 
> On Wed, 2020-06-10 at 20:23 +0800, Frankie Chang wrote:
> > Frankie.Chang (3):
> >   binder: move structs from core file to header file
> >   binder: add trace at free transaction.
> >   binder: add transaction latency tracer
> > 
> >  drivers/android/Kconfig |   8 +
> >  drivers/android/Makefile|   1 +
> >  drivers/android/binder.c| 408 +--
> >  drivers/android/binder_internal.h   | 416 
> >  drivers/android/binder_latency_tracer.c | 108 ++
> >  drivers/android/binder_trace.h  |  49 +++
> >  6 files changed, 586 insertions(+), 404 deletions(-)  create mode 100644 
> > drivers/android/binder_latency_tracer.c
> > 
> > Change from v5:
> >   - change config name to the proper one, 
> > CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
> >   - change tracepoint name to more descriptive one, 
> > trace_binder_txn_latency_(alloc|info|free)
> >   - enhance some lock protection.
> > 
> > Change from v4:
> >   - split up into patch series.
> > 
> > Change from v3:
> >   - use tracepoints for binder_update_info and print_binder_transaction_ext,
> > instead of custom registration functions.
> > 
> > Change from v2:
> >   - create transaction latency module to monitor slow transaction.
> > 
> > Change from v1:
> >   - first patchset.
> 

Re: [PATCH v5] binder: transaction latency tracking for user build

[Frankie Chang]

Hi Greg, Todd and all

Gentle remind of this patch set

Thanks.
Frankie

On Wed, 2020-06-10 at 20:23 +0800, Frankie Chang wrote:
> Frankie.Chang (3):
>   binder: move structs from core file to header file
>   binder: add trace at free transaction.
>   binder: add transaction latency tracer
> 
>  drivers/android/Kconfig |   8 +
>  drivers/android/Makefile|   1 +
>  drivers/android/binder.c| 408 +--
>  drivers/android/binder_internal.h   | 416 
>  drivers/android/binder_latency_tracer.c | 108 ++
>  drivers/android/binder_trace.h  |  49 +++
>  6 files changed, 586 insertions(+), 404 deletions(-)  create mode 100644 
> drivers/android/binder_latency_tracer.c
> 
> Change from v5:
>   - change config name to the proper one, 
> CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
>   - change tracepoint name to more descriptive one, 
> trace_binder_txn_latency_(alloc|info|free)
>   - enhance some lock protection.
> 
> Change from v4:
>   - split up into patch series.
> 
> Change from v3:
>   - use tracepoints for binder_update_info and print_binder_transaction_ext,
> instead of custom registration functions.
> 
> Change from v2:
>   - create transaction latency module to monitor slow transaction.
> 
> Change from v1:
>   - first patchset.

[PATCH v5] binder: transaction latency tracking for user build

[Frankie Chang]

Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 408 +--
 drivers/android/binder_internal.h   | 416 
 drivers/android/binder_latency_tracer.c | 108 ++
 drivers/android/binder_trace.h  |  49 +++
 6 files changed, 586 insertions(+), 404 deletions(-)  create mode 100644 
drivers/android/binder_latency_tracer.c

Change from v5:
  - change config name to the proper one, 
CONFIG_BINDER_TRANSACTION_LATENCY_TRACKING.
  - change tracepoint name to more descriptive one, 
trace_binder_txn_latency_(alloc|info|free)
  - enhance some lock protection.

Change from v4:
  - split up into patch series.

Change from v3:
  - use tracepoints for binder_update_info and print_binder_transaction_ext,
instead of custom registration functions.

Change from v2:
  - create transaction latency module to monitor slow transaction.

Change from v1:
  - first patchset.

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

[Frankie Chang]

On Thu, 2020-05-07 at 11:21 -0700, Todd Kjos wrote:
> On Thu, May 7, 2020 at 1:11 AM Frankie Chang  
> wrote:
> >
> > From: "Frankie.Chang" 
> >
> > 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 this is a hard-coded threshold, provide rationale for why 2 sec is
> the right value and it doesn't need to be tunable
> 

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, we want to record related transactions which exceed 2 sec. It
could be helpful to debug.

> > if yes, printing related information for tracing.
> >
> > /* Implement details */
> > - Add latency tracer module to monitor slow transaction.
> >   The trace_binder_free_transaction 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.
> 
> Please add a more complete description. This patch adds a module to
> monitor transaction latency by attaching to new tracepoints introduced
> when transactions are allocated and freed. Describe this in the commit
> message.
> 

Okay, we would add these description in next version.

> >
> > Signed-off-by: Frankie.Chang 
> > ---
> >  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 |  105 
> > +++
> >  drivers/android/binder_trace.h  |   26 +++-
> >  6 files changed, 152 insertions(+), 3 deletions(-)
> >  create mode 100644 drivers/android/binder_latency_tracer.c
> >
> >  Change from v4:
> >split up into patch series.
> >
> >  Change from v3:
> >use tracepoints for binder_update_info and print_binder_transaction_ext,
> >instead of custom registration functions.
> >
> >  Change from v2:
> >create transaction latency module to monitor slow transaction.
> >
> >  Change from v1:
> >first patchset.
> >
> > diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
> > index 6fdf2ab..7ba80eb 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_USER_TRACKING
> 
> Why not "BINDER_TRANSACTION_LATENCY_TRACKING"?
> 

Thanks for your advice. We would modify the config name to this proper
one.

> > +   bool "Android Binder transaction tracking"
> > +   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 detail info about it.
> 
> "If yes, print out the detailed info"
> 

We would modify it, thanks.

> > +
> >  endif # if ANDROID
> >
> >  endmenu
> > diff --git a/drivers/android/Makefile b/drivers/android/Makefile
> > index c9d3d0c9..552e8ac 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_USER_TRACKING) += binder_latency_tracer.o
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 4c3dd98..b89d75a 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_update_info(t, e);
> 
> Can this be a more descriptive name? Perhaps "trace_binder_txn_create()"
> 

Okay, we would replace the original name with
trace_binder_txn_latency_alloc.

> >  

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

[Frankie Chang]

On Thu, 2020-05-07 at 10:55 +0200, Greg Kroah-Hartman wrote:
> On Thu, May 07, 2020 at 04:10:55PM +0800, Frankie Chang wrote:
> > From: "Frankie.Chang" 
> > 
> > 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.
> 
> Shouldn't that "printing" go to the trace buffer and not to the kernel
> information log?
> 

Time limitation of recording is the reason why we don't just use trace
here.

In some long time stability test, such as MTBF,
the exception is caused by a series of transactions interaction.
Some abnormal transactions may be pending for a long time ago, they 
could not be recorded due to buffer limited.

> > 
> > /* Implement details */
> > - Add latency tracer module to monitor slow transaction.
> >   The trace_binder_free_transaction 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.
> > 
> > Signed-off-by: Frankie.Chang 
> > ---
> >  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 |  105 
> > +++
> >  drivers/android/binder_trace.h  |   26 +++-
> >  6 files changed, 152 insertions(+), 3 deletions(-)
> >  create mode 100644 drivers/android/binder_latency_tracer.c
> > 
> >  Change from v4:
> >split up into patch series.
> > 
> >  Change from v3:
> >use tracepoints for binder_update_info and print_binder_transaction_ext,
> >instead of custom registration functions.
> > 
> >  Change from v2:
> >create transaction latency module to monitor slow transaction.
> > 
> >  Change from v1:
> >first patchset.
> > 
> > diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
> > index 6fdf2ab..7ba80eb 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_USER_TRACKING
> > +   bool "Android Binder transaction tracking"
> > +   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 detail info about it.
> > +
> >  endif # if ANDROID
> >  
> >  endmenu
> > diff --git a/drivers/android/Makefile b/drivers/android/Makefile
> > index c9d3d0c9..552e8ac 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_USER_TRACKING) += binder_latency_tracer.o
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 4c3dd98..b89d75a 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_update_info(t, e);
> > INIT_LIST_HEAD(&t->fd_fixups);
> > binder_stats_created(BINDER_STAT_TRANSACTION);
> > spin_lock_init(&t->lock);
> > @@ -5145,6 +5146,7 @@ static void print_binder_transaction_ilocked(struct 
> > seq_file *m,
> >t->to_thread ? t->to_thread->pid : 0,
> >t->code, t->flags, t->priority, t->need_reply);
> > spin_unlock(&t->lock);
> > +   trace_print_binder_transaction_ext(m, t);
> >  
> > if (proc != to_proc) {
> > /*
> > diff --git a/drivers/android/binder_internal.h 
> > b/drivers/android/binder_internal.h
> > index ed61b3e..24d7beb 100644
> > --- a/drivers/an

binder: transaction latency tracking for user build

[Frankie Chang]

Frankie.Chang (3):
  binder: move structs from core file to header file
  binder: add trace at free transaction.
  binder: add transaction latency tracer

 drivers/android/Kconfig |   8 +
 drivers/android/Makefile|   1 +
 drivers/android/binder.c| 408 +--
 drivers/android/binder_internal.h   | 416 
 drivers/android/binder_latency_tracer.c | 105 ++
 drivers/android/binder_trace.h  |  47 +++
 6 files changed, 581 insertions(+), 404 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

[PATCH v3 1/1] binder: transaction latency tracking for user build

[Frankie Chang]

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 tracepoint/trace at free transaction.
  Since the original trace_binder_transaction_received cannot
  precisely present the real finished time of transaction, adding a
  trace_binder_free_transaction at the point of free transaction
  may be more close to it.

- Add latency tracer module to monitor slow transaction.
  The trace_binder_free_transaction 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.

- Move some struct from core file to header file.
  Need some struct defined in core file in latency trace module
  In addition, moving all structs to header file makes module
  more extendable, and make all these strcuts to be defined
  in the same file.

Signed-off-by: Frankie Chang 
---
 drivers/android/Kconfig |8 +
 drivers/android/Makefile|1 +
 drivers/android/binder.c|  408 +-
 drivers/android/binder_internal.h   |  416 +++
 drivers/android/binder_latency_tracer.c |  105 
 drivers/android/binder_trace.h  |   49 
 6 files changed, 583 insertions(+), 404 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
index 6fdf2ab..7ba80eb 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_USER_TRACKING
+   bool "Android Binder transaction tracking"
+   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 detail info about it.
+
 endif # if ANDROID
 
 endmenu
diff --git a/drivers/android/Makefile b/drivers/android/Makefile
index c9d3d0c9..552e8ac 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_USER_TRACKING) += binder_latency_tracer.o
diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index a6b2082..b89d75a 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -160,24 +160,6 @@ static int binder_set_stop_on_user_error(const char *val,
 #define to_binder_fd_array_object(hdr) \
container_of(hdr, struct binder_fd_array_object, hdr)
 
-enum binder_stat_types {
-   BINDER_STAT_PROC,
-   BINDER_STAT_THREAD,
-   BINDER_STAT_NODE,
-   BINDER_STAT_REF,
-   BINDER_STAT_DEATH,
-   BINDER_STAT_TRANSACTION,
-   BINDER_STAT_TRANSACTION_COMPLETE,
-   BINDER_STAT_COUNT
-};
-
-struct binder_stats {
-   atomic_t br[_IOC_NR(BR_FAILED_REPLY) + 1];
-   atomic_t bc[_IOC_NR(BC_REPLY_SG) + 1];
-   atomic_t obj_created[BINDER_STAT_COUNT];
-   atomic_t obj_deleted[BINDER_STAT_COUNT];
-};
-
 static struct binder_stats binder_stats;
 
 static inline void binder_stats_deleted(enum binder_stat_types type)
@@ -213,278 +195,11 @@ static struct binder_transaction_log_entry 
*binder_transaction_log_add(
return e;
 }
 
-/**
- * struct binder_work - work enqueued on a worklist
- * @entry: node enqueued on list
- * @type:  type of work to be performed
- *
- * There are separate work lists for proc, thread, and node (async).
- */
-struct binder_work {
-   struct list_head entry;
-
-   enum {
-   BINDER_WORK_TRANSACTION = 1,
-   BINDER_WORK_TRANSACTION_COMPLETE,
-   BINDER_WORK_RETURN_ERROR,
-   BINDER_WORK_NODE,
-   BINDER_WORK_DEAD_BINDER,
-   BINDER_WORK_DEAD_BINDER_AND_CLEAR,
-   BINDER_WORK_CLEAR_DEATH_NOTIFICATION,
-   } type;
-};
-
-struct binder_error {
-   struct binder_work work;
-   uint32_t cmd;
-};
-
-/**
- * struct binder_node - binder node bookkeeping
- * @debug_id: unique ID for debugging
- *(invariant after initialized)
- * @lock: lock for node fields
- * @work: worklist element for node work
- *(protected by @proc->inner_lock)
- * @rb_node:  element for proc->nodes tree
- *(protected by @

binder: transaction latency tracking for user build

[Frankie Chang]

Frankie Chang (1):
  binder: transaction latency tracking for user build

 drivers/android/Kconfig |8 +
 drivers/android/Makefile|1 +
 drivers/android/binder.c|  408 +-
 drivers/android/binder_internal.h   |  416 +++
 drivers/android/binder_latency_tracer.c |  105 
 drivers/android/binder_trace.h  |   49 
 6 files changed, 583 insertions(+), 404 deletions(-)
 create mode 100644 drivers/android/binder_latency_tracer.c

Re: [PATCH v2 1/1] binder: transaction latency tracking for user build

[Frankie Chang]

On Wed, 2020-04-15 at 15:25 -0700, Todd Kjos wrote:
> On Tue, Apr 14, 2020 at 10:38 PM Frankie Chang
>  wrote:
> >
> > Record start/end timestamp to binder transaction.
> 
> s/timestamp to/timestamps for/
> 
> > When transaction is completed or transaction is free,
> > it would be checked if transaction latency over threshold (2 sec),
> 
> Is the 2 sec configurable? Why was 2 sec chosen?

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, we want to record these transactions which exceed 2 sec. It
could be helpful to debug.

> > if yes, printing related information for tracing.
> >
> > /* Implement details */
> > - Add tracepoint/trace at free transaction.
> >   Since the original trace_binder_transaction_reveived cannot
> 
> s/reveived/received/
> 
> >   precisely present the real finished time of transaction, adding a
> >   trace_binder_free_transaction at the point of free transaction
> >   may be more close to it.
> 
> Can we just add that trace instead?

Time limitation of recording is the reason why we don't just use trace
here.

In some long time stability test, such as MTBF,
the exception is caused by a series of transactions interaction.
Some abnormal transactions may be pending for a long time ago, they 
could not be recorded due to buffer limited. 

> >
> > - Add latency tracer module to monitor slow transaction.
> >   The trace_binder_free_transaction 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.
> >
> > - Move some struct from core file to header file.
> >   Need some struct defined in core file in latency trace module
> >   In addition, moving structs to header file makes module more
> >   extendable.
> >
> > Signed-off-by: Frankie Chang 
> > ---
> >  drivers/android/Kconfig |8 ++
> >  drivers/android/Makefile|1 +
> >  drivers/android/binder.c|  237 
> > ---
> >  drivers/android/binder_internal.h   |  227 
> > +
> >  drivers/android/binder_latency_tracer.c |  100 +
> >  drivers/android/binder_trace.h  |   36 +
> >  6 files changed, 400 insertions(+), 209 deletions(-)
> >  create mode 100644 drivers/android/binder_latency_tracer.c
> >
> > diff --git a/drivers/android/Kconfig b/drivers/android/Kconfig
> > index 6fdf2ab..7ba80eb 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_USER_TRACKING
> > +   bool "Android Binder transaction tracking"
> > +   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 detail info about it.
> > +
> >  endif # if ANDROID
> >
> >  endmenu
> > diff --git a/drivers/android/Makefile b/drivers/android/Makefile
> > index c9d3d0c9..552e8ac 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_USER_TRACKING) += binder_latency_tracer.o
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index a6b2082..380a68b 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -160,24 +160,6 @@ static int binder_set_stop_on_user_error(const char 
> > *val,
> >  #define to_binder_fd_array_object(hdr) \
> > container_of(hdr, struct binder_fd_array_object, hdr)
> >
> > -enum binder_stat_types {
> > -   BINDER_STAT_PROC,
> > -   BINDER_STAT_THREAD,
> > -   BINDER_STAT_NODE,
> > -   BINDER_STAT_REF,
> > -   BINDER_STAT_DEATH,
> > -   BINDER_STAT_TRANSACTION,
> > -   BINDER_STAT_TRANSACTION_COMPLET