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

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

Posted by Chuang Zhang 2 years, 8 months ago

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.

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

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

Posted by Carlos Llamas 2 years, 8 months ago

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

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

Posted by Greg KH 2 years, 8 months ago

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