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

[Carlos Llamas <cmllamas@google.com>]

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.

Can you clarify how are you using this information? It seems the
timestamp here is only applicable for in-flight transactions correct?
Also, why not use the current trace points to generate this information?
The standard to measure transaction latency seems to be Perfetto.

> 
> Signed-off-by: Chuang Zhang <zhangchuang3@xiaomi.com>
> ---
>  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();

The start_time will be more accurate if taken earlier. Several spinlocks
will delay the timestamp here. You can cache this value in a local
variable upon entry, actually similar to the t_debug_id.

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

The t->from is not populated for oneway transactions as it is not safe
to access. However, I don't see a reason for not populating the from_pid
and from_tid in synchronous here. Why make this async only?

> +	} else  {
>  		t->from = NULL;
> +		t->async_from_pid = thread->proc->pid;

nit: just proc->pid is shorter and equivalent.

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

You could always use t->from_pid and t->from_tid here regardless if
t->from is populated or not. But as mentioned above, you'd need to drop
the async only portion.

>  		   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;
> +	ktime_t start_time;
>  	struct list_head fd_fixups;
>  	binder_uintptr_t security_ctx;
>  	/**
> -- 
> 2.34.1
> 

Thanks,
Carlos Llamas