Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record

[Greg KH <gregkh@linuxfoundation.org>]

On Thu, Apr 13, 2023 at 06:40:47PM +0800, Chuang Zhang wrote:
> From: Chuang Zhang <zhangchuang3@xiaomi.com>
> 
> This patch adds a timestamp field to the binder_transaction
> structure to track the time consumed during transmission
> when reading binder_transaction records.
> Additionally, it records the from pid and tid of asynchronous
> binder. This information is printed when reading binderfs
> related nodes to assist with debugging.

This should be broken up into 2 patches, one for each new feature you
are adding, right?

> 
> Signed-off-by: Chuang Zhang <zhangchuang3@xiaomi.com>

Much better, thanks!

Some comments on the code:

> ---
>  drivers/android/binder.c          | 24 ++++++++++++++++++------
>  drivers/android/binder_internal.h |  3 +++
>  2 files changed, 21 insertions(+), 6 deletions(-)
> 
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index fb56bfc45096..e79f548bcbac 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -66,6 +66,7 @@
>  #include <linux/syscalls.h>
>  #include <linux/task_work.h>
>  #include <linux/sizes.h>
> +#include <linux/ktime.h>
>  
>  #include <uapi/linux/android/binder.h>
>  
> @@ -3145,6 +3146,7 @@ static void binder_transaction(struct binder_proc *proc,
>  	binder_stats_created(BINDER_STAT_TRANSACTION_COMPLETE);
>  
>  	t->debug_id = t_debug_id;
> +	t->start_time = ktime_get();
>  
>  	if (reply)
>  		binder_debug(BINDER_DEBUG_TRANSACTION,
> @@ -3165,10 +3167,15 @@ static void binder_transaction(struct binder_proc *proc,
>  			     (u64)tr->data_size, (u64)tr->offsets_size,
>  			     (u64)extra_buffers_size);
>  
> -	if (!reply && !(tr->flags & TF_ONE_WAY))
> +	if (!reply && !(tr->flags & TF_ONE_WAY)) {
>  		t->from = thread;
> -	else
> +		t->async_from_pid = 0;
> +		t->async_from_tid = 0;
> +	} else  {
>  		t->from = NULL;
> +		t->async_from_pid = thread->proc->pid;
> +		t->async_from_tid = thread->pid;
> +	}
>  	t->sender_euid = task_euid(proc->tsk);
>  	t->to_proc = target_proc;
>  	t->to_thread = target_thread;
> @@ -4963,6 +4970,8 @@ static int binder_thread_release(struct binder_proc *proc,
>  		} else if (t->from == thread) {
>  			t->from = NULL;
>  			t = t->from_parent;
> +			t->async_from_pid = 0;
> +			t->async_from_tid = 0;
>  		} else
>  			BUG();
>  		spin_unlock(&last_t->lock);
> @@ -5930,17 +5939,20 @@ static void print_binder_transaction_ilocked(struct seq_file *m,
>  {
>  	struct binder_proc *to_proc;
>  	struct binder_buffer *buffer = t->buffer;
> +	ktime_t current_time = ktime_get();
>  
>  	spin_lock(&t->lock);
>  	to_proc = t->to_proc;
>  	seq_printf(m,
> -		   "%s %d: %pK from %d:%d to %d:%d code %x flags %x pri %ld r%d",
> +		   "%s %d: %pK from %d:%d to %d:%d code %x elapsed %lldms flags %x pri %ld r%d",

Why not add this at the end of the line instead of in the middle?  That
way any existing code that looks at this line isn't as broken as it
might be with your change :)

>  		   prefix, t->debug_id, t,
> -		   t->from ? t->from->proc->pid : 0,
> -		   t->from ? t->from->pid : 0,
> +		   t->from ? t->from->proc->pid : t->async_from_pid,
> +		   t->from ? t->from->pid : t->async_from_tid,
>  		   to_proc ? to_proc->pid : 0,
>  		   t->to_thread ? t->to_thread->pid : 0,
> -		   t->code, t->flags, t->priority, t->need_reply);
> +		   t->code,
> +		   ktime_ms_delta(current_time, t->start_time),
> +		   t->flags, t->priority, t->need_reply);
>  	spin_unlock(&t->lock);
>  
>  	if (proc != to_proc) {
> diff --git a/drivers/android/binder_internal.h b/drivers/android/binder_internal.h
> index 28ef5b3704b1..7e60f547abb6 100644
> --- a/drivers/android/binder_internal.h
> +++ b/drivers/android/binder_internal.h
> @@ -528,6 +528,9 @@ struct binder_transaction {
>  	long    priority;
>  	long    saved_priority;
>  	kuid_t  sender_euid;
> +	int async_from_pid;
> +	int async_from_tid;

As you are just using 0/1 for these variables, why not add them to the
bitfield location in this structure instead of wasting a whole int for
both of them?

thanks,

greg k-h