public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
* [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
@ 2023-04-13  9:38 Chuang Zhang
  2023-04-13 10:17 ` Greg KH
  0 siblings, 1 reply; 9+ messages in thread
From: Chuang Zhang @ 2023-04-13  9:38 UTC (permalink / raw)
  To: gregkh
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	zhangchuang3

From: zhangchuang3 <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: zhangchuang3 <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


^ permalink raw reply related	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
  2023-04-13  9:38 Chuang Zhang
@ 2023-04-13 10:17 ` Greg KH
  0 siblings, 0 replies; 9+ messages in thread
From: Greg KH @ 2023-04-13 10:17 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	zhangchuang3

On Thu, Apr 13, 2023 at 05:38:05PM +0800, Chuang Zhang wrote:
> From: zhangchuang3 <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: zhangchuang3 <zhangchuang3@xiaomi.com>

As I said before, use your hame, not your email alias.

And do NOT send the patch from a gmail account, otherwise I have no way
to verify that you really are a developer at xiaomi.com, right?

thanks,

greg k-h

^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
@ 2023-04-13 10:40 Chuang Zhang
  2023-04-13 10:51 ` Greg KH
  2023-04-14 21:03 ` Carlos Llamas
  0 siblings, 2 replies; 9+ messages in thread
From: Chuang Zhang @ 2023-04-13 10:40 UTC (permalink / raw)
  To: gregkh
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	Chuang Zhang

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


^ permalink raw reply related	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
  2023-04-13 10:40 [PATCH] Binder: Add timestamp and async from pid/tid to transaction record Chuang Zhang
@ 2023-04-13 10:51 ` Greg KH
       [not found]   ` <CAO+dPF9KFJe5h4wO47ypL2-__3+1mnzurdRcj6OCQ1wdku_7cA@mail.gmail.com>
  2023-04-14 21:03 ` Carlos Llamas
  1 sibling, 1 reply; 9+ messages in thread
From: Greg KH @ 2023-04-13 10:51 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	Chuang Zhang

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
       [not found]   ` <CAO+dPF9KFJe5h4wO47ypL2-__3+1mnzurdRcj6OCQ1wdku_7cA@mail.gmail.com>
@ 2023-04-13 12:17     ` Greg KH
       [not found]       ` <CAO+dPF-YNtaZvVax8Z1QD9VtG36uc2C=uus4eR4H_vipEzu8Dw@mail.gmail.com>
  0 siblings, 1 reply; 9+ messages in thread
From: Greg KH @ 2023-04-13 12:17 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	Chuang Zhang

On Thu, Apr 13, 2023 at 07:33:26PM +0800, Chuang Zhang wrote:
> On Thu, Apr 13, 2023 at 6:51 PM Greg KH <gregkh@linuxfoundation.org> wrote:
> > >       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 :)
> >
> >> [chuang] Ok, so move it after t->need_reply or buffer->user_data?

After need_reply?

> > > --- 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?
> >
> >> [chuang] They are used to store the caller's process ID and thread ID,
> not just 1 or 0, so I understand that integers are still needed to save
> them. thanks!

Ah, I missed that these really were the pid itself.  Then an int will
not work at all, it has to be pid_t, right?

And how are pid namespaces being handled here?  I know it's just
debugging data but showing a pid from the wrong namespace probably would
not be a good idea as it might get confusing quickly.

thanks,

greg k-h

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
       [not found]       ` <CAO+dPF-YNtaZvVax8Z1QD9VtG36uc2C=uus4eR4H_vipEzu8Dw@mail.gmail.com>
@ 2023-04-13 12:36         ` Greg KH
       [not found]           ` <CAO+dPF8inueprEXeNMBWZtiqDzcjFQLbKLVq+qL0gGq3gRBu3w@mail.gmail.com>
  0 siblings, 1 reply; 9+ messages in thread
From: Greg KH @ 2023-04-13 12:36 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	Chuang Zhang

On Thu, Apr 13, 2023 at 08:34:06PM +0800, Chuang Zhang wrote:
> On Thu, Apr 13, 2023 at 8:17 PM Greg KH <gregkh@linuxfoundation.org> wrote:
> > And how are pid namespaces being handled here?  I know it's just
> > debugging data but showing a pid from the wrong namespace probably would
> > not be a good idea as it might get confusing quickly.
> >
> [chuang] Do you have any good suggestions? thanks

I do not know what you are using this debug information for, nor how or
if Android uses pid namespaces (I think it does?)

Maybe the binder maintainers can help answer this question...

thanks,

greg k-h

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
       [not found]           ` <CAO+dPF8inueprEXeNMBWZtiqDzcjFQLbKLVq+qL0gGq3gRBu3w@mail.gmail.com>
@ 2023-04-13 15:06             ` Greg KH
  0 siblings, 0 replies; 9+ messages in thread
From: Greg KH @ 2023-04-13 15:06 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: arve, tkjos, maco, joel, brauner, cmllamas, surenb, linux-kernel,
	Chuang Zhang

On Thu, Apr 13, 2023 at 09:03:08PM +0800, Chuang Zhang wrote:
> On Thu, Apr 13, 2023 at 8:36 PM Greg KH <gregkh@linuxfoundation.org> wrote:
> 
> > On Thu, Apr 13, 2023 at 08:34:06PM +0800, Chuang Zhang wrote:
> > > On Thu, Apr 13, 2023 at 8:17 PM Greg KH <gregkh@linuxfoundation.org>
> > wrote:
> > > > And how are pid namespaces being handled here?  I know it's just
> > > > debugging data but showing a pid from the wrong namespace probably
> > would
> > > > not be a good idea as it might get confusing quickly.
> > > >
> > > [chuang] Do you have any good suggestions? thanks
> >
> > I do not know what you are using this debug information for, nor how or
> > if Android uses pid namespaces (I think it does?)
> >
> [chuang]
> So can I use (struct binder_thread *async_from) instead ?
> and get the corresponding pid and tid through the following way:
> async_from->proc->pid
> async_from->pid

I don't know, try it and see!

I'm not quite sure what debugging information you can get here with the
pid, nor what you intend to do with it, so I can't answer this very
well, sorry.

thanks,

greg k-h

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
  2023-04-13 10:40 [PATCH] Binder: Add timestamp and async from pid/tid to transaction record Chuang Zhang
  2023-04-13 10:51 ` Greg KH
@ 2023-04-14 21:03 ` Carlos Llamas
       [not found]   ` <CAO+dPF9cb5tQzNkuO4hniTfWesACbr4z2YvT8XKj4afFgyYjjw@mail.gmail.com>
  1 sibling, 1 reply; 9+ messages in thread
From: Carlos Llamas @ 2023-04-14 21:03 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: gregkh, arve, tkjos, maco, joel, brauner, surenb, linux-kernel,
	Chuang Zhang

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH] Binder: Add timestamp and async from pid/tid to transaction record
       [not found]   ` <CAO+dPF9cb5tQzNkuO4hniTfWesACbr4z2YvT8XKj4afFgyYjjw@mail.gmail.com>
@ 2023-04-20 14:28     ` Carlos Llamas
  0 siblings, 0 replies; 9+ messages in thread
From: Carlos Llamas @ 2023-04-20 14:28 UTC (permalink / raw)
  To: Chuang Zhang
  Cc: Greg KH, arve, tkjos, maco, joel, brauner, surenb, linux-kernel,
	Chuang Zhang

On Mon, Apr 17, 2023 at 03:14:55PM +0800, Chuang Zhang wrote:
> 
> [chuang]  Android's ANR and Watchdog problems are often caused by calling
> Binder's server interface and waiting synchronously for too long. In order
> to
> confirm this root-casue, we need to let system_server read the relevant
> nodes
>  of binderfs to obtain the transmission when the above failure occurs
> information,
> including of course the time-consuming of the transmission.
> He will help many Android application and system engineers to quickly
> analyze related faults.
> Because we need to obtain time-consuming information in real time when ANR
> or Watchdog occurs, this happens more when consumers use it, and they
> cannot effectively capture atrace, so Perfetto cannot be applied.

Fair enough, this sounds good to me then.

> 
> [chuang]As you can see below, in fact, we only need to print the PID and
> TID
> of "from" when printing binder transaction records in
> print_binder_transaction_ilocked,
> which can be printed correctly regardless of whether it is asynchronous or
> synchronous.
> It is just because the PID and TID of "from" can be obtained through
> t->from in
> synchronous mode, while t->from in asynchronous mode cannot be obtained
> because it is not populated.
> So can I directly add new variables from_pid and from_tid to record all
> transmissions? Does it matter if the naming includes the pid? Greg has
> expressed some concerns about this before .

Right, lets populate t->from_pid and t->from_tid for all transactions
and use those only in print_binder_transaction() instead of t->from.
As Greg mentioned, please add these in a separate commit.

About the namespaces, Greg's comments seem accurate. Binder is using the
task->pid directly so the PIDs would not match those seen by the
namespace. This points to a larger issue in binder as we log these
"raw" pid values everywhere. I'll look further into this and come up
with a binder global fix in a separate commit, so just ignore for now.

Thanks,
--
Carlos Llamas

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2023-04-20 14:28 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-04-13 10:40 [PATCH] Binder: Add timestamp and async from pid/tid to transaction record Chuang Zhang
2023-04-13 10:51 ` Greg KH
     [not found]   ` <CAO+dPF9KFJe5h4wO47ypL2-__3+1mnzurdRcj6OCQ1wdku_7cA@mail.gmail.com>
2023-04-13 12:17     ` Greg KH
     [not found]       ` <CAO+dPF-YNtaZvVax8Z1QD9VtG36uc2C=uus4eR4H_vipEzu8Dw@mail.gmail.com>
2023-04-13 12:36         ` Greg KH
     [not found]           ` <CAO+dPF8inueprEXeNMBWZtiqDzcjFQLbKLVq+qL0gGq3gRBu3w@mail.gmail.com>
2023-04-13 15:06             ` Greg KH
2023-04-14 21:03 ` Carlos Llamas
     [not found]   ` <CAO+dPF9cb5tQzNkuO4hniTfWesACbr4z2YvT8XKj4afFgyYjjw@mail.gmail.com>
2023-04-20 14:28     ` Carlos Llamas
  -- strict thread matches above, loose matches on Subject: below --
2023-04-13  9:38 Chuang Zhang
2023-04-13 10:17 ` Greg KH

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox