linux-mediatek.lists.infradead.org archive mirror
 help / color / mirror / Atom feed
From: Todd Kjos <tkjos@google.com>
To: Frankie Chang <Frankie.Chang@mediatek.com>
Cc: wsd_upstream <wsd_upstream@mediatek.com>,
	"Greg Kroah-Hartman" <gregkh@linuxfoundation.org>,
	LKML <linux-kernel@vger.kernel.org>,
	"Arve Hjønnevåg" <arve@android.com>,
	"Jian-Min Liu" <Jian-Min.Liu@mediatek.com>,
	linux-mediatek@lists.infradead.org,
	"Joel Fernandes" <joel@joelfernandes.org>,
	"Martijn Coenen" <maco@android.com>,
	"Christian Brauner" <christian@brauner.io>
Subject: Re: [PATCH v4 3/3] binder: add transaction latency tracer
Date: Thu, 7 May 2020 11:21:38 -0700	[thread overview]
Message-ID: <CAHRSSEwqxiJqbaMHVPMWPPpLiy_raa-Zncr3VBPpcwpRbTzThg@mail.gmail.com> (raw)
In-Reply-To: <1588839055-26677-4-git-send-email-Frankie.Chang@mediatek.com>

On Thu, May 7, 2020 at 1:11 AM Frankie Chang <Frankie.Chang@mediatek.com> wrote:
>
> From: "Frankie.Chang" <Frankie.Chang@mediatek.com>
>
> Record start/end timestamp for binder transaction.
> When transaction is completed or transaction is free,
> it would be checked if transaction latency over threshold (2 sec),

If this is a hard-coded threshold, provide rationale for why 2 sec is
the right value and it doesn't need to be tunable

> 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.

>
> Signed-off-by: Frankie.Chang <Frankie.Chang@mediatek.com>
> ---
>  drivers/android/Kconfig                 |    8 +++
>  drivers/android/Makefile                |    1 +
>  drivers/android/binder.c                |    2 +
>  drivers/android/binder_internal.h       |   13 ++++
>  drivers/android/binder_latency_tracer.c |  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"?

> +       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"

> +
>  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()"

>         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);

Why do you need to trace when dumping out the transaction info?

>
>         if (proc != to_proc) {
>                 /*
> diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> index ed61b3e..24d7beb 100644
> --- a/drivers/android/binder_internal.h
> +++ b/drivers/android/binder_internal.h
> @@ -12,6 +12,11 @@
>  #include <linux/types.h>
>  #include <linux/uidgid.h>
>
> +#ifdef CONFIG_BINDER_USER_TRACKING
> +#include <linux/rtc.h>
> +#include <linux/time.h>
> +#endif
> +
>  struct binder_context {
>         struct binder_node *binder_context_mgr_node;
>         struct mutex context_mgr_node_lock;
> @@ -131,6 +136,10 @@ struct binder_transaction_log_entry {
>         uint32_t return_error;
>         uint32_t return_error_param;
>         char context_name[BINDERFS_MAX_NAME + 1];
> +#ifdef CONFIG_BINDER_USER_TRACKING
> +       struct timespec timestamp;
> +       struct timeval tv;
> +#endif
>  };
>
>  struct binder_transaction_log {
> @@ -520,6 +529,10 @@ struct binder_transaction {
>          * during thread teardown
>          */
>         spinlock_t lock;
> +#ifdef CONFIG_BINDER_USER_TRACKING
> +       struct timespec timestamp;
> +       struct timeval tv;
> +#endif
>  };
>
>  /**
> diff --git a/drivers/android/binder_latency_tracer.c b/drivers/android/binder_latency_tracer.c
> new file mode 100644
> index 0000000..45c14fb
> --- /dev/null
> +++ b/drivers/android/binder_latency_tracer.c
> @@ -0,0 +1,105 @@
> +// SPDX-License-Identifier: GPL-2.0
> +/*
> + * Copyright (C) 2019 MediaTek Inc.
> + */
> +
> +#include <linux/module.h>
> +#include <uapi/linux/android/binder.h>
> +#include "binder_alloc.h"
> +#include "binder_internal.h"
> +#include "binder_trace.h"
> +
> +/*
> + * probe_binder_free_transaction - Output info of a delay transaction
> + * @t:          pointer to the over-time transaction
> + */
> +void probe_binder_free_transaction(void *ignore, struct binder_transaction *t)
> +{
> +       struct rtc_time tm;
> +       struct timespec *startime;
> +       struct timespec cur, sub_t;
> +
> +       ktime_get_ts(&cur);
> +       startime = &t->timestamp;
> +       sub_t = timespec_sub(cur, *startime);
> +
> +       /* if transaction time is over than 2 sec,
> +        * show timeout warning log.
> +        */
> +       if (sub_t.tv_sec < 2)
> +               return;
> +
> +       rtc_time_to_tm(t->tv.tv_sec, &tm);
> +
> +       spin_lock(&t->lock);
> +       pr_info_ratelimited("%d: from %d:%d to %d:%d",
> +                       t->debug_id,
> +                       t->from ? t->from->proc->pid : 0,
> +                       t->from ? t->from->pid : 0,
> +                       t->to_proc ? t->to_proc->pid : 0,
> +                       t->to_thread ? t->to_thread->pid : 0);
> +       spin_unlock(&t->lock);
> +
> +       pr_info_ratelimited(" total %u.%03ld s code %u start %lu.%03ld android %d-%02d-%02d %02d:%02d:%02d.%03lu\n",
> +                       (unsigned int)sub_t.tv_sec,
> +                       (sub_t.tv_nsec / NSEC_PER_MSEC),
> +                       t->code,
> +                       (unsigned long)startime->tv_sec,
> +                       (startime->tv_nsec / NSEC_PER_MSEC),
> +                       (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
> +                       tm.tm_hour, tm.tm_min, tm.tm_sec,
> +                       (unsigned long)(t->tv.tv_usec / USEC_PER_MSEC));
> +}
> +
> +static void probe_binder_update_info(void *ignore, struct binder_transaction *t,
> +                          struct binder_transaction_log_entry *e)
> +{
> +       ktime_get_ts(&e->timestamp);
> +       do_gettimeofday(&e->tv);
> +       e->tv.tv_sec -= (sys_tz.tz_minuteswest * 60);
> +       memcpy(&t->timestamp, &e->timestamp, sizeof(struct timespec));
> +       memcpy(&t->tv, &e->tv, sizeof(struct timeval));
> +}
> +
> +static void probe_print_binder_transaction_ext(void *ignore, struct seq_file *m,
> +                                        struct binder_transaction *t)
> +{
> +       struct rtc_time tm;
> +
> +       rtc_time_to_tm(t->tv.tv_sec, &tm);
> +       seq_printf(m,
> +                  " start %lu.%06lu android %d-%02d-%02d %02d:%02d:%02d.%03lu",
> +                  (unsigned long)t->timestamp.tv_sec,
> +                  (t->timestamp.tv_nsec / NSEC_PER_USEC),
> +                  (tm.tm_year + 1900), (tm.tm_mon + 1), tm.tm_mday,
> +                  tm.tm_hour, tm.tm_min, tm.tm_sec,
> +                  (unsigned long)(t->tv.tv_usec / USEC_PER_MSEC));
> +
> +}
> +
> +static int __init init_binder_latency_tracer(void)
> +{
> +       register_trace_binder_free_transaction(
> +                       probe_binder_free_transaction, NULL);
> +       register_trace_binder_update_info(
> +                       probe_binder_update_info, NULL);
> +       register_trace_print_binder_transaction_ext(
> +                       probe_print_binder_transaction_ext, NULL);

Ah, now the trace in the print path makes sense. Please add a more
detailed description to the commit message. Also add a comment at the
trace point that it is for modules to attach to so additional
information can be printed. Also, make the names of the tracepoints
more descriptive of what they really are ...something like
trace_binder_txn_latency_(alloc|info|free)

> +
> +       return 0;
> +}
> +
> +static void exit_binder_latency_tracer(void)
> +{
> +       unregister_trace_binder_free_transaction(
> +                       probe_binder_free_transaction, NULL);
> +       unregister_trace_binder_update_info(
> +                       probe_binder_update_info, NULL);
> +       unregister_trace_print_binder_transaction_ext(
> +                       probe_print_binder_transaction_ext, NULL);
> +}
> +
> +module_init(init_binder_latency_tracer);
> +module_exit(exit_binder_latency_tracer);
> +
> +MODULE_LICENSE("GPL v2");
> diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
> index 7acc18d..466993e 100644
> --- a/drivers/android/binder_trace.h
> +++ b/drivers/android/binder_trace.h
> @@ -18,6 +18,7 @@
>  struct binder_ref_data;
>  struct binder_thread;
>  struct binder_transaction;
> +struct binder_transaction_log_entry;
>
>  TRACE_EVENT(binder_ioctl,
>         TP_PROTO(unsigned int cmd, unsigned long arg),
> @@ -95,6 +96,18 @@
>                   __entry->thread_todo)
>  );
>
> +DECLARE_TRACE(binder_update_info,
> +       TP_PROTO(struct binder_transaction *t,
> +                struct binder_transaction_log_entry *e),
> +       TP_ARGS(t, e)
> +);
> +
> +DECLARE_TRACE(print_binder_transaction_ext,
> +       TP_PROTO(struct seq_file *m,
> +                struct binder_transaction *t),
> +       TP_ARGS(m, t)
> +);
> +
>  TRACE_EVENT(binder_free_transaction,
>         TP_PROTO(struct binder_transaction *t),
>         TP_ARGS(t),
> @@ -115,11 +128,18 @@
>                 __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
>                 __entry->code = t->code;
>                 __entry->flags = t->flags;
> -       ),
> -       TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
> +#ifdef CONFIG_BINDER_USER_TRACKING
> +               __entry->start_sec = t->timestamp.tv_sec;
> +               __entry->start_nsec = t->timestamp.tv_nsec / NSEC_PER_MSEC;
> +#else
> +               __entry->start_sec = 0;
> +               __entry->start_nsec = 0;
> +#endif
> +       ),
> +       TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x start %lu.%03ld",
>                   __entry->debug_id, __entry->from_proc, __entry->from_thread,
>                   __entry->to_proc, __entry->to_thread, __entry->code,
> -                 __entry->flags)
> +                 __entry->flags, __entry->start_sec, __entry->start_nsec)
>  );
>
>  TRACE_EVENT(binder_transaction,
> --
> 1.7.9.5

_______________________________________________
Linux-mediatek mailing list
Linux-mediatek@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-mediatek

  parent reply	other threads:[~2020-05-07 18:22 UTC|newest]

Thread overview: 72+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2020-02-05  6:52 [PATCH v1 1/1] binder: transaction latency tracking for user build Frankie Chang
2020-02-05  9:36 ` Greg Kroah-Hartman
2020-02-05 15:49   ` Joel Fernandes
2020-02-07  3:10     ` Frankie Chang
2020-02-07  3:17       ` Joel Fernandes
2020-02-07  6:28         ` Frankie Chang
2020-02-07 13:26           ` Joel Fernandes
2020-04-13  6:24             ` Frankie Chang
2020-04-15  5:37               ` [PATCH v2] " Frankie Chang
2020-04-15  5:37                 ` [PATCH v2 1/1] " Frankie Chang
2020-04-15 22:25                   ` Todd Kjos
2020-04-29  8:32                     ` Frankie Chang
2020-04-30  8:13                   ` Frankie Chang
2020-04-30  8:13                     ` [PATCH v3 1/1] " Frankie Chang
2020-04-30  8:50                       ` Greg Kroah-Hartman
2020-04-30  8:51                       ` Greg Kroah-Hartman
2020-05-07  8:10                         ` Frankie Chang
2020-05-07  8:10                           ` [PATCH v4 1/3] binder: move structs from core file to header file Frankie Chang
2020-05-07  8:10                           ` [PATCH v4 2/3] binder: add trace at free transaction Frankie Chang
2020-05-07  8:10                           ` [PATCH v4 3/3] binder: add transaction latency tracer Frankie Chang
2020-05-07  8:55                             ` Greg Kroah-Hartman
2020-05-11 12:32                               ` Frankie Chang
2020-06-10 12:23                               ` [PATCH v5] binder: transaction latency tracking for user build Frankie Chang
2020-06-10 12:23                                 ` [PATCH v5 1/3] binder: move structs from core file to header file Frankie Chang
2020-06-10 12:23                                 ` [PATCH v5 2/3] binder: add trace at free transaction Frankie Chang
2020-07-20 18:23                                   ` Todd Kjos
2020-07-23  2:47                                     ` Frankie Chang
2020-06-10 12:23                                 ` [PATCH v5 3/3] binder: add transaction latency tracer Frankie Chang
2020-07-20 18:56                                   ` Todd Kjos
2020-07-23  3:01                                     ` Frankie Chang
2020-07-02 13:25                                 ` [PATCH v5] binder: transaction latency tracking for user build Frankie Chang
2020-07-20 13:40                                   ` Frankie Chang
2020-07-28  3:19                                     ` [PATCH v6] " Frankie Chang
2020-07-28  3:19                                       ` [PATCH v6 1/3] binder: move structs from core file to header file Frankie Chang
2020-07-28  3:20                                       ` [PATCH v6 2/3] binder: add trace at free transaction Frankie Chang
2020-07-31 18:50                                         ` Todd Kjos
2020-08-03  3:11                                           ` Frankie Chang
2020-08-03 15:12                                             ` Todd Kjos
2020-08-04  2:45                                               ` Frankie Chang
2020-08-04 13:59                                                 ` [PATCH v7] binder: transaction latency tracking for user build Frankie Chang
2020-08-04 13:59                                                   ` [PATCH v7 1/3] binder: move structs from core file to header file Frankie Chang
2020-08-04 15:24                                                     ` Todd Kjos
2020-08-04 13:59                                                   ` [PATCH v7 2/3] binder: add trace at free transaction Frankie Chang
2020-08-04 15:26                                                     ` Todd Kjos
2020-08-04 13:59                                                   ` [PATCH v7 3/3] binder: add transaction latency tracer Frankie Chang
2020-08-04 15:28                                                     ` Todd Kjos
2020-09-07 14:41                                                     ` peter enderborg
2020-09-03 16:21                                                   ` [PATCH v7] binder: transaction latency tracking for user build Greg Kroah-Hartman
2020-09-07  6:49                                                     ` Frankie Chang
2020-09-07  7:00                                                       ` Greg Kroah-Hartman
2020-09-07 12:00                                                         ` [PATCH v8] " Frankie Chang
2020-09-07 12:00                                                           ` [PATCH v8 1/3] binder: move structs from core file to header file Frankie Chang
2020-09-07 12:00                                                           ` [PATCH v8 2/3] binder: add trace at free transaction Frankie Chang
2020-09-07 12:00                                                           ` [PATCH v8 3/3] binder: add transaction latency tracer Frankie Chang
2020-09-07 12:25                                                             ` Greg Kroah-Hartman
2020-09-07 13:51                                                               ` Frankie Chang
2020-09-07 14:09                                                                 ` Greg Kroah-Hartman
2020-09-08  5:38                                                                   ` Frankie Chang
2020-09-08 14:06                                                                     ` [PATCH v9] binder: transaction latency tracking for user build Frankie Chang
2020-09-08 14:06                                                                       ` [PATCH v9 1/3] binder: move structs from core file to header file Frankie Chang
2020-09-08 14:06                                                                       ` [PATCH v9 2/3] binder: add trace at free transaction Frankie Chang
2020-09-08 14:06                                                                       ` [PATCH v9 3/3] binder: add transaction latency tracer Frankie Chang
2020-09-16 17:38                                                                         ` Greg Kroah-Hartman
2020-10-15 17:02                                                                           ` [PATCH v10 " Frankie Chang
2020-10-15 17:02                                                                             ` [PATCH v10 1/3] binder: move structs from core file to header file Frankie Chang
2020-10-15 17:02                                                                             ` [PATCH v10 2/3] binder: add trace at free transaction Frankie Chang
2020-10-15 17:02                                                                             ` [PATCH v10 3/3] binder: add transaction latency tracer Frankie Chang
2020-09-16 15:29                                                                       ` [PATCH v9] binder: transaction latency tracking for user build Greg Kroah-Hartman
2020-09-07 12:24                                                           ` [PATCH v8] " Greg Kroah-Hartman
2020-07-28  3:20                                       ` [PATCH v6 3/3] binder: add transaction latency tracer Frankie Chang
2020-05-07 18:21                             ` Todd Kjos [this message]
2020-05-11 12:35                               ` [PATCH v4 " Frankie Chang

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=CAHRSSEwqxiJqbaMHVPMWPPpLiy_raa-Zncr3VBPpcwpRbTzThg@mail.gmail.com \
    --to=tkjos@google.com \
    --cc=Frankie.Chang@mediatek.com \
    --cc=Jian-Min.Liu@mediatek.com \
    --cc=arve@android.com \
    --cc=christian@brauner.io \
    --cc=gregkh@linuxfoundation.org \
    --cc=joel@joelfernandes.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-mediatek@lists.infradead.org \
    --cc=maco@android.com \
    --cc=wsd_upstream@mediatek.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).