* [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
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
* [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
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