Re: [PATCH v2 1/1] binder: transaction latency tracking for user build
From: Frankie Chang
Date: Wed Apr 29 2020 - 04:32:30 EST
On Wed, 2020-04-15 at 15:25 -0700, Todd Kjos wrote:
> On Tue, Apr 14, 2020 at 10:38 PM Frankie Chang
> <Frankie.Chang@xxxxxxxxxxxx> 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 <Frankie.Chang@xxxxxxxxxxxx>
> > ---
> > 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_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)
> > @@ -214,32 +196,6 @@ static struct binder_transaction_log_entry *binder_transaction_log_add(
> > }
> >
> > /**
> > - * 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)
>
> Please, if we must have a binder_internal.h for the key data
> structures, then move them all.
> The use of structs by transaction latency stuff shouldn't be the
> rationale for what moves and
> what stays. binder_proc, binder_node, binder_thread etc should be defined
> in the same file.
Okay, we will move all structs to binder_internal.h to make them defined in same file, thanks.
> > @@ -402,89 +358,6 @@ enum binder_deferred_state {
> > BINDER_DEFERRED_RELEASE = 0x02,
> > };
> >
> > -/**
> > - * struct binder_proc - binder process bookkeeping
> > - * @proc_node: element for binder_procs list
> > - * @threads: rbtree of binder_threads in this proc
> > - * (protected by @inner_lock)
> > - * @nodes: rbtree of binder nodes associated with
> > - * this proc ordered by node->ptr
> > - * (protected by @inner_lock)
> > - * @refs_by_desc: rbtree of refs ordered by ref->desc
> > - * (protected by @outer_lock)
> > - * @refs_by_node: rbtree of refs ordered by ref->node
> > - * (protected by @outer_lock)
> > - * @waiting_threads: threads currently waiting for proc work
> > - * (protected by @inner_lock)
> > - * @pid PID of group_leader of process
> > - * (invariant after initialized)
> > - * @tsk task_struct for group_leader of process
> > - * (invariant after initialized)
> > - * @deferred_work_node: element for binder_deferred_list
> > - * (protected by binder_deferred_lock)
> > - * @deferred_work: bitmap of deferred work to perform
> > - * (protected by binder_deferred_lock)
> > - * @is_dead: process is dead and awaiting free
> > - * when outstanding transactions are cleaned up
> > - * (protected by @inner_lock)
> > - * @todo: list of work for this process
> > - * (protected by @inner_lock)
> > - * @stats: per-process binder statistics
> > - * (atomics, no lock needed)
> > - * @delivered_death: list of delivered death notification
> > - * (protected by @inner_lock)
> > - * @max_threads: cap on number of binder threads
> > - * (protected by @inner_lock)
> > - * @requested_threads: number of binder threads requested but not
> > - * yet started. In current implementation, can
> > - * only be 0 or 1.
> > - * (protected by @inner_lock)
> > - * @requested_threads_started: number binder threads started
> > - * (protected by @inner_lock)
> > - * @tmp_ref: temporary reference to indicate proc is in use
> > - * (protected by @inner_lock)
> > - * @default_priority: default scheduler priority
> > - * (invariant after initialized)
> > - * @debugfs_entry: debugfs node
> > - * @alloc: binder allocator bookkeeping
> > - * @context: binder_context for this proc
> > - * (invariant after initialized)
> > - * @inner_lock: can nest under outer_lock and/or node lock
> > - * @outer_lock: no nesting under innor or node lock
> > - * Lock order: 1) outer, 2) node, 3) inner
> > - * @binderfs_entry: process-specific binderfs log file
> > - *
> > - * Bookkeeping structure for binder processes
> > - */
> > -struct binder_proc {
> > - struct hlist_node proc_node;
> > - struct rb_root threads;
> > - struct rb_root nodes;
> > - struct rb_root refs_by_desc;
> > - struct rb_root refs_by_node;
> > - struct list_head waiting_threads;
> > - int pid;
> > - struct task_struct *tsk;
> > - struct hlist_node deferred_work_node;
> > - int deferred_work;
> > - bool is_dead;
> > -
> > - struct list_head todo;
> > - struct binder_stats stats;
> > - struct list_head delivered_death;
> > - int max_threads;
> > - int requested_threads;
> > - int requested_threads_started;
> > - int tmp_ref;
> > - long default_priority;
> > - struct dentry *debugfs_entry;
> > - struct binder_alloc alloc;
> > - struct binder_context *context;
> > - spinlock_t inner_lock;
> > - spinlock_t outer_lock;
> > - struct dentry *binderfs_entry;
> > -};
> > -
> > enum {
> > BINDER_LOOPER_STATE_REGISTERED = 0x01,
> > BINDER_LOOPER_STATE_ENTERED = 0x02,
> > @@ -495,60 +368,6 @@ enum {
> > };
> >
> > /**
> > - * struct binder_thread - binder thread bookkeeping
> > - * @proc: binder process for this thread
> > - * (invariant after initialization)
> > - * @rb_node: element for proc->threads rbtree
> > - * (protected by @proc->inner_lock)
> > - * @waiting_thread_node: element for @proc->waiting_threads list
> > - * (protected by @proc->inner_lock)
> > - * @pid: PID for this thread
> > - * (invariant after initialization)
> > - * @looper: bitmap of looping state
> > - * (only accessed by this thread)
> > - * @looper_needs_return: looping thread needs to exit driver
> > - * (no lock needed)
> > - * @transaction_stack: stack of in-progress transactions for this thread
> > - * (protected by @proc->inner_lock)
> > - * @todo: list of work to do for this thread
> > - * (protected by @proc->inner_lock)
> > - * @process_todo: whether work in @todo should be processed
> > - * (protected by @proc->inner_lock)
> > - * @return_error: transaction errors reported by this thread
> > - * (only accessed by this thread)
> > - * @reply_error: transaction errors reported by target thread
> > - * (protected by @proc->inner_lock)
> > - * @wait: wait queue for thread work
> > - * @stats: per-thread statistics
> > - * (atomics, no lock needed)
> > - * @tmp_ref: temporary reference to indicate thread is in use
> > - * (atomic since @proc->inner_lock cannot
> > - * always be acquired)
> > - * @is_dead: thread is dead and awaiting free
> > - * when outstanding transactions are cleaned up
> > - * (protected by @proc->inner_lock)
> > - *
> > - * Bookkeeping structure for binder threads.
> > - */
> > -struct binder_thread {
> > - struct binder_proc *proc;
> > - struct rb_node rb_node;
> > - struct list_head waiting_thread_node;
> > - int pid;
> > - int looper; /* only modified by this thread */
> > - bool looper_need_return; /* can be written by other thread */
> > - struct binder_transaction *transaction_stack;
> > - struct list_head todo;
> > - bool process_todo;
> > - struct binder_error return_error;
> > - struct binder_error reply_error;
> > - wait_queue_head_t wait;
> > - struct binder_stats stats;
> > - atomic_t tmp_ref;
> > - bool is_dead;
> > -};
> > -
> > -/**
> > * struct binder_txn_fd_fixup - transaction fd fixup list element
> > * @fixup_entry: list entry
> > * @file: struct file to be associated with new fd
> > @@ -565,34 +384,6 @@ struct binder_txn_fd_fixup {
> > size_t offset;
> > };
> >
> >
>
> extra empty line?
>
> > -struct binder_transaction {
> > - int debug_id;
> > - struct binder_work work;
> > - struct binder_thread *from;
> > - struct binder_transaction *from_parent;
> > - struct binder_proc *to_proc;
> > - struct binder_thread *to_thread;
> > - struct binder_transaction *to_parent;
> > - unsigned need_reply:1;
> > - /* unsigned is_dead:1; */ /* not used at the moment */
> > -
> > - struct binder_buffer *buffer;
> > - unsigned int code;
> > - unsigned int flags;
> > - long priority;
> > - long saved_priority;
> > - kuid_t sender_euid;
> > - struct list_head fd_fixups;
> > - binder_uintptr_t security_ctx;
> > - /**
> > - * @lock: protects @from, @to_proc, and @to_thread
> > - *
> > - * @from, @to_proc, and @to_thread can be set to NULL
> > - * during thread teardown
> > - */
> > - spinlock_t lock;
> > -};
> > -
> > /**
> > * struct binder_object - union of flat binder object types
> > * @hdr: generic object header
> > @@ -613,6 +404,26 @@ struct binder_object {
> > };
> > };
> >
> > +static void (*__binder_update_info_cb)(struct binder_transaction *t,
> > + struct binder_transaction_log_entry *e);
> > +
> > +void set_binder_update_info_cb(void (*fn)(struct binder_transaction *t,
> > + struct binder_transaction_log_entry *e))
> > +{
> > + __binder_update_info_cb = fn;
> > +}
> > +EXPORT_SYMBOL_GPL(set_binder_update_info_cb);
> > +
> > +static void (*__print_transaction_ext_cb)(struct seq_file *m,
> > + struct binder_transaction *t);
> > +
> > +void set_print_transaction_ext_cb(void (*fn)(struct seq_file *m,
> > + struct binder_transaction *t))
> > +{
> > + __print_transaction_ext_cb = fn;
> > +}
> > +EXPORT_SYMBOL_GPL(set_print_transaction_ext_cb);
>
> Why can't we use tracepoints (not trace events) for this instead of
> custom registration functions? You can attach to the tracepoint with
> register_trace_* lets a module register to be called to handle the
> tracepoint as Joel pointed out.
Yes, we will use tracepoints instead of custom registration functions in
next version patch, thanks.
> > +
> > /**
> > * binder_proc_lock() - Acquire outer lock for given binder_proc
> > * @proc: struct binder_proc to acquire
> > @@ -1927,6 +1738,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_free_transaction(t);
> > binder_free_txn_fixups(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > @@ -2874,6 +2686,7 @@ static void binder_transaction(struct binder_proc *proc,
> > e->offsets_size = tr->offsets_size;
> > strscpy(e->context_name, proc->context->name, BINDERFS_MAX_NAME);
> >
> > +
>
> why 2 empty lines?
>
> > if (reply) {
> > binder_inner_proc_lock(proc);
> > in_reply_to = thread->transaction_stack;
> > @@ -3060,6 +2873,9 @@ static void binder_transaction(struct binder_proc *proc,
> > return_error_line = __LINE__;
> > goto err_alloc_t_failed;
> > }
> > +
> > + if (__binder_update_info_cb)
> > + __binder_update_info_cb(t, e);
>
> This should be a tracepoint that your module can attach to with
> register_trace_binder_update_info(...)
>
> > INIT_LIST_HEAD(&t->fd_fixups);
> > binder_stats_created(BINDER_STAT_TRANSACTION);
> > spin_lock_init(&t->lock);
> > @@ -3498,6 +3314,7 @@ static void binder_transaction(struct binder_proc *proc,
> > kfree(tcomplete);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> > err_alloc_tcomplete_failed:
> > + trace_binder_free_transaction(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > err_alloc_t_failed:
> > @@ -5547,6 +5364,8 @@ 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);
> > + if (__print_transaction_ext_cb)
> > + __print_transaction_ext_cb(m, t);
>
> same here.
>
> >
> > if (proc != to_proc) {
> > /*
> > diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> > index ae99109..86b4960 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 {
> > @@ -139,6 +148,224 @@ struct binder_transaction_log {
> > struct binder_transaction_log_entry entry[32];
> > };
> >
> > +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];
> > +};
> > +
> > +/**
> > + * 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_proc - binder process bookkeeping
> > + * @proc_node: element for binder_procs list
> > + * @threads: rbtree of binder_threads in this proc
> > + * (protected by @inner_lock)
> > + * @nodes: rbtree of binder nodes associated with
> > + * this proc ordered by node->ptr
> > + * (protected by @inner_lock)
> > + * @refs_by_desc: rbtree of refs ordered by ref->desc
> > + * (protected by @outer_lock)
> > + * @refs_by_node: rbtree of refs ordered by ref->node
> > + * (protected by @outer_lock)
> > + * @waiting_threads: threads currently waiting for proc work
> > + * (protected by @inner_lock)
> > + * @pid PID of group_leader of process
> > + * (invariant after initialized)
> > + * @tsk task_struct for group_leader of process
> > + * (invariant after initialized)
> > + * @deferred_work_node: element for binder_deferred_list
> > + * (protected by binder_deferred_lock)
> > + * @deferred_work: bitmap of deferred work to perform
> > + * (protected by binder_deferred_lock)
> > + * @is_dead: process is dead and awaiting free
> > + * when outstanding transactions are cleaned up
> > + * (protected by @inner_lock)
> > + * @todo: list of work for this process
> > + * (protected by @inner_lock)
> > + * @stats: per-process binder statistics
> > + * (atomics, no lock needed)
> > + * @delivered_death: list of delivered death notification
> > + * (protected by @inner_lock)
> > + * @max_threads: cap on number of binder threads
> > + * (protected by @inner_lock)
> > + * @requested_threads: number of binder threads requested but not
> > + * yet started. In current implementation, can
> > + * only be 0 or 1.
> > + * (protected by @inner_lock)
> > + * @requested_threads_started: number binder threads started
> > + * (protected by @inner_lock)
> > + * @tmp_ref: temporary reference to indicate proc is in use
> > + * (protected by @inner_lock)
> > + * @default_priority: default scheduler priority
> > + * (invariant after initialized)
> > + * @debugfs_entry: debugfs node
> > + * @alloc: binder allocator bookkeeping
> > + * @context: binder_context for this proc
> > + * (invariant after initialized)
> > + * @inner_lock: can nest under outer_lock and/or node lock
> > + * @outer_lock: no nesting under innor or node lock
> > + * Lock order: 1) outer, 2) node, 3) inner
> > + * @binderfs_entry: process-specific binderfs log file
> > + *
> > + * Bookkeeping structure for binder processes
> > + */
> > +struct binder_proc {
> > + struct hlist_node proc_node;
> > + struct rb_root threads;
> > + struct rb_root nodes;
> > + struct rb_root refs_by_desc;
> > + struct rb_root refs_by_node;
> > + struct list_head waiting_threads;
> > + int pid;
> > + struct task_struct *tsk;
> > + struct hlist_node deferred_work_node;
> > + int deferred_work;
> > + bool is_dead;
> > +
> > + struct list_head todo;
> > + struct binder_stats stats;
> > + struct list_head delivered_death;
> > + int max_threads;
> > + int requested_threads;
> > + int requested_threads_started;
> > + int tmp_ref;
> > + long default_priority;
> > + struct dentry *debugfs_entry;
> > + struct binder_alloc alloc;
> > + struct binder_context *context;
> > + spinlock_t inner_lock;
> > + spinlock_t outer_lock;
> > + struct dentry *binderfs_entry;
> > +};
> > +
> > +/**
> > + * struct binder_thread - binder thread bookkeeping
> > + * @proc: binder process for this thread
> > + * (invariant after initialization)
> > + * @rb_node: element for proc->threads rbtree
> > + * (protected by @proc->inner_lock)
> > + * @waiting_thread_node: element for @proc->waiting_threads list
> > + * (protected by @proc->inner_lock)
> > + * @pid: PID for this thread
> > + * (invariant after initialization)
> > + * @looper: bitmap of looping state
> > + * (only accessed by this thread)
> > + * @looper_needs_return: looping thread needs to exit driver
> > + * (no lock needed)
> > + * @transaction_stack: stack of in-progress transactions for this thread
> > + * (protected by @proc->inner_lock)
> > + * @todo: list of work to do for this thread
> > + * (protected by @proc->inner_lock)
> > + * @process_todo: whether work in @todo should be processed
> > + * (protected by @proc->inner_lock)
> > + * @return_error: transaction errors reported by this thread
> > + * (only accessed by this thread)
> > + * @reply_error: transaction errors reported by target thread
> > + * (protected by @proc->inner_lock)
> > + * @wait: wait queue for thread work
> > + * @stats: per-thread statistics
> > + * (atomics, no lock needed)
> > + * @tmp_ref: temporary reference to indicate thread is in use
> > + * (atomic since @proc->inner_lock cannot
> > + * always be acquired)
> > + * @is_dead: thread is dead and awaiting free
> > + * when outstanding transactions are cleaned up
> > + * (protected by @proc->inner_lock)
> > + *
> > + * Bookkeeping structure for binder threads.
> > + */
> > +struct binder_thread {
> > + struct binder_proc *proc;
> > + struct rb_node rb_node;
> > + struct list_head waiting_thread_node;
> > + int pid;
> > + int looper; /* only modified by this thread */
> > + bool looper_need_return; /* can be written by other thread */
> > + struct binder_transaction *transaction_stack;
> > + struct list_head todo;
> > + bool process_todo;
> > + struct binder_error return_error;
> > + struct binder_error reply_error;
> > + wait_queue_head_t wait;
> > + struct binder_stats stats;
> > + atomic_t tmp_ref;
> > + bool is_dead;
> > +};
> > +
> > +struct binder_transaction {
> > + int debug_id;
> > + struct binder_work work;
> > + struct binder_thread *from;
> > + struct binder_transaction *from_parent;
> > + struct binder_proc *to_proc;
> > + struct binder_thread *to_thread;
> > + struct binder_transaction *to_parent;
> > + unsigned need_reply:1;
> > + /* unsigned is_dead:1; */ /* not used at the moment */
> > +
> > + struct binder_buffer *buffer;
> > + unsigned int code;
> > + unsigned int flags;
> > + long priority;
> > + long saved_priority;
> > + kuid_t sender_euid;
> > + struct list_head fd_fixups;
> > + binder_uintptr_t security_ctx;
> > + /**
> > + * @lock: protects @from, @to_proc, and @to_thread
> > + *
> > + * @from, @to_proc, and @to_thread can be set to NULL
> > + * during thread teardown
> > + */
> > + spinlock_t lock;
> > +#ifdef CONFIG_BINDER_USER_TRACKING
> > + struct timespec timestamp;
> > + struct timeval tv;
> > +#endif
> > +};
> > +
> > extern struct binder_transaction_log binder_transaction_log;
> > extern struct binder_transaction_log binder_transaction_log_failed;
> > +
> > +extern void set_binder_update_info_cb(void (*fn)(struct binder_transaction *t,
> > + struct binder_transaction_log_entry *e));
> > +extern void set_print_transaction_ext_cb(void (*fn)(struct seq_file *m,
> > + struct binder_transaction *t));
> > #endif /* _LINUX_BINDER_INTERNAL_H */
> > diff --git a/drivers/android/binder_latency_tracer.c b/drivers/android/binder_latency_tracer.c
> > new file mode 100644
> > index 0000000..c9626f5
> > --- /dev/null
> > +++ b/drivers/android/binder_latency_tracer.c
> > @@ -0,0 +1,100 @@
> > +// 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 binder_update_info_cb(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 print_binder_transaction_ext(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);
> > +
> > + set_binder_update_info_cb(binder_update_info_cb);
> > + set_print_transaction_ext_cb(print_binder_transaction_ext);
> > + return 0;
> > +}
> > +
> > +static void exit_binder_latency_tracer(void)
> > +{
> > + unregister_trace_binder_free_transaction(
> > + probe_binder_free_transaction, 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 6731c3c..c7c76c1 100644
> > --- a/drivers/android/binder_trace.h
> > +++ b/drivers/android/binder_trace.h
> > @@ -95,6 +95,42 @@
> > __entry->thread_todo)
> > );
> >
> > +TRACE_EVENT(binder_free_transaction,
> > + 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)
> > + __field(unsigned long, start_sec)
> > + __field(unsigned long, start_nsec)
> > + ),
> > + 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;
> > +#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->start_sec, __entry->start_nsec)
> > +);
> > +
> > TRACE_EVENT(binder_transaction,
> > TP_PROTO(bool reply, struct binder_transaction *t,
> > struct binder_node *target_node),
> > --
> > 1.7.9.5