Re: [PATCH v6 2/3] binder: add trace at free transaction.
On Mon, 2020-08-03 at 08:12 -0700, Todd Kjos wrote:
> On Sun, Aug 2, 2020 at 8:11 PM Frankie Chang
> wrote:
> >
> > On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> > > On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
> > > wrote:
> > > >
> > > > From: "Frankie.Chang"
> > > >
> > > > Since the original trace_binder_transaction_received cannot
> > > > precisely present the real finished time of transaction, adding a
> > > > trace_binder_txn_latency_free at the point of free transaction
> > > > may be more close to it.
> > > >
> > > > Signed-off-by: Frankie.Chang
> > > > ---
> > > > drivers/android/binder.c |6 ++
> > > > drivers/android/binder_trace.h | 27 +++
> > > > 2 files changed, 33 insertions(+)
> > > >
> > > > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > > > index 2df146f..1e6fc40 100644
> > > > --- a/drivers/android/binder.c
> > > > +++ b/drivers/android/binder.c
> > > > @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct
> > > > binder_transaction *t)
> > > > * If the transaction has no target_proc, then
> > > > * t->buffer->transaction has already been cleared.
> > > > */
> > > > + spin_lock(>lock);
> > > > + trace_binder_txn_latency_free(t);
> > > > + spin_unlock(>lock);
> > >
> > > Hmm. I don't prefer taking the lock just to call a trace. It doesn't
> > > make clear why the lock has to be taken. I'd prefer something like:
> > >
> > > if (trace_binder_txn_latency_free_enabled()) {
> > c
> > > }
> > >
> > > And then the trace would use the passed-in values instead of accessing
> > > via t->to_proc/to_thread.
> > >
> > Then we still add lock protection in the hook function, when trace is
> > disable ?
>
> I don't understand... in the example I gave, the trace doesn't get
> called if disabled. What do you mean to "add lock protection when the
> trace is disabled()"?
>
> >
> > Or we also pass these to hook function, no matter the trace is enable or
>
> What do you mean by "hook" function? If something has attached to the
> trace, then xxx_enabled() will return true.
>
I'm sorry for that I misunderstand this XXX_enabled().
> > not.I think this way is more clear that the lock protects @from,
> > @to_proc and @to_thread.Then, there is no need to add the lock in hook
> > function.
>
> Why is it clearer (other than the fact that I missed including t->from
> under the lock)?
>
I think your example is clear enough.
> >
> > int from_proc, from_thread, to_proc, to_thread;
> >
> > spin_lock(>lock);
> > from_proc = t->from ? t->from->proc->pid : 0;
> > from_thread = t->from ? t->from->pid :0;
> > to_proc = t->to_proc ? t->to_proc->pid : 0;
> > to_thread = t->to_thread ? t->to_thread->pid : 0;
> > spin_unlock(>lock);
> > trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc,
> > to_pid);
>
> The main feedback is I'd like to see the fields dereferenced in the
> same context as the lock acquisition instead of acquiring the lock and
> calling the trace function, so this code would be fine. There will be
> very little contention for t->lock so using xxx_enabled() is optional.
>
> Since trace_binder_txn_latency_free() is called twice, it would make
> sense to have a helper function to do the above.
>
Okay, I will make a helper function to do this in next version patch.
Very thanks for your help for this.
> >
> > > > binder_free_txn_fixups(t);
> > > > kfree(t);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > > @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc
> > > > *proc,
> > > > kfree(tcomplete);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> > > > err_alloc_tcomplete_failed:
> > > > + spin_lock(>lock);
> > > > + trace_binder_txn_latency_free(t);
> > > > + spin_unlock(>lock);
> > > > kfree(t);
> > > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > > err_alloc_t_failed:
> > > > diff --git a/drivers/android/binder_trace.h
> > > > b/drivers/android/binder_trace.h
> > > > index 6731c3c..8ac87d1 100644
> > > > --- a/drivers/android/binder_trace.h
> > > > +++ b/drivers/android/binder_trace.h
> > > > @@ -95,6 +95,33 @@
> > > > __entry->thread_todo)
> > > > );
> > > >
> > > > +TRACE_EVENT(binder_txn_latency_free,
> > > > + TP_PROTO(struct binder_transaction *t),
> > > > + TP_ARGS(t),
> > > > + TP_STRUCT__entry(
> > > > + __field(int, debug_id)
> > > > + __field(int, from_proc)
> > > > + __field(int, from_thread)
> > > > + __field(int, to_proc)
> > > > + __field(int, to_thread)
> > > > + __field(unsigned int, code)
> > > > + __field(unsigned int, flags)
> > > > + ),
> > > > + TP_fast_assign(
> > > > + __entry->debug_id = t->debug_id;
> > > > + __entry->from_proc
Re: [PATCH v6 2/3] binder: add trace at free transaction.
On Sun, Aug 2, 2020 at 8:11 PM Frankie Chang wrote:
>
> On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> > On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
> > wrote:
> > >
> > > From: "Frankie.Chang"
> > >
> > > Since the original trace_binder_transaction_received cannot
> > > precisely present the real finished time of transaction, adding a
> > > trace_binder_txn_latency_free at the point of free transaction
> > > may be more close to it.
> > >
> > > Signed-off-by: Frankie.Chang
> > > ---
> > > drivers/android/binder.c |6 ++
> > > drivers/android/binder_trace.h | 27 +++
> > > 2 files changed, 33 insertions(+)
> > >
> > > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > > index 2df146f..1e6fc40 100644
> > > --- a/drivers/android/binder.c
> > > +++ b/drivers/android/binder.c
> > > @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct
> > > binder_transaction *t)
> > > * If the transaction has no target_proc, then
> > > * t->buffer->transaction has already been cleared.
> > > */
> > > + spin_lock(>lock);
> > > + trace_binder_txn_latency_free(t);
> > > + spin_unlock(>lock);
> >
> > Hmm. I don't prefer taking the lock just to call a trace. It doesn't
> > make clear why the lock has to be taken. I'd prefer something like:
> >
> > if (trace_binder_txn_latency_free_enabled()) {
> c
> > }
> >
> > And then the trace would use the passed-in values instead of accessing
> > via t->to_proc/to_thread.
> >
> Then we still add lock protection in the hook function, when trace is
> disable ?
I don't understand... in the example I gave, the trace doesn't get
called if disabled. What do you mean to "add lock protection when the
trace is disabled()"?
>
> Or we also pass these to hook function, no matter the trace is enable or
What do you mean by "hook" function? If something has attached to the
trace, then xxx_enabled() will return true.
> not.I think this way is more clear that the lock protects @from,
> @to_proc and @to_thread.Then, there is no need to add the lock in hook
> function.
Why is it clearer (other than the fact that I missed including t->from
under the lock)?
>
> int from_proc, from_thread, to_proc, to_thread;
>
> spin_lock(>lock);
> from_proc = t->from ? t->from->proc->pid : 0;
> from_thread = t->from ? t->from->pid :0;
> to_proc = t->to_proc ? t->to_proc->pid : 0;
> to_thread = t->to_thread ? t->to_thread->pid : 0;
> spin_unlock(>lock);
> trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc,
> to_pid);
The main feedback is I'd like to see the fields dereferenced in the
same context as the lock acquisition instead of acquiring the lock and
calling the trace function, so this code would be fine. There will be
very little contention for t->lock so using xxx_enabled() is optional.
Since trace_binder_txn_latency_free() is called twice, it would make
sense to have a helper function to do the above.
>
> > > binder_free_txn_fixups(t);
> > > kfree(t);
> > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc
> > > *proc,
> > > kfree(tcomplete);
> > > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> > > err_alloc_tcomplete_failed:
> > > + spin_lock(>lock);
> > > + trace_binder_txn_latency_free(t);
> > > + spin_unlock(>lock);
> > > kfree(t);
> > > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > > err_alloc_t_failed:
> > > diff --git a/drivers/android/binder_trace.h
> > > b/drivers/android/binder_trace.h
> > > index 6731c3c..8ac87d1 100644
> > > --- a/drivers/android/binder_trace.h
> > > +++ b/drivers/android/binder_trace.h
> > > @@ -95,6 +95,33 @@
> > > __entry->thread_todo)
> > > );
> > >
> > > +TRACE_EVENT(binder_txn_latency_free,
> > > + TP_PROTO(struct binder_transaction *t),
> > > + TP_ARGS(t),
> > > + TP_STRUCT__entry(
> > > + __field(int, debug_id)
> > > + __field(int, from_proc)
> > > + __field(int, from_thread)
> > > + __field(int, to_proc)
> > > + __field(int, to_thread)
> > > + __field(unsigned int, code)
> > > + __field(unsigned int, flags)
> > > + ),
> > > + TP_fast_assign(
> > > + __entry->debug_id = t->debug_id;
> > > + __entry->from_proc = t->from ? t->from->proc->pid : 0;
> > > + __entry->from_thread = t->from ? t->from->pid : 0;
> > > + __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
> > > + __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
> > > + __entry->code = t->code;
> > > + __entry->flags = t->flags;
> > > + ),
> > > + TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x
> > > code=0x%x",
> > > +
Re: [PATCH v6 2/3] binder: add trace at free transaction.
On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
> wrote:
> >
> > From: "Frankie.Chang"
> >
> > Since the original trace_binder_transaction_received cannot
> > precisely present the real finished time of transaction, adding a
> > trace_binder_txn_latency_free at the point of free transaction
> > may be more close to it.
> >
> > Signed-off-by: Frankie.Chang
> > ---
> > drivers/android/binder.c |6 ++
> > drivers/android/binder_trace.h | 27 +++
> > 2 files changed, 33 insertions(+)
> >
> > diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> > index 2df146f..1e6fc40 100644
> > --- a/drivers/android/binder.c
> > +++ b/drivers/android/binder.c
> > @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct
> > binder_transaction *t)
> > * If the transaction has no target_proc, then
> > * t->buffer->transaction has already been cleared.
> > */
> > + spin_lock(>lock);
> > + trace_binder_txn_latency_free(t);
> > + spin_unlock(>lock);
>
> Hmm. I don't prefer taking the lock just to call a trace. It doesn't
> make clear why the lock has to be taken. I'd prefer something like:
>
> if (trace_binder_txn_latency_free_enabled()) {
c
> }
>
> And then the trace would use the passed-in values instead of accessing
> via t->to_proc/to_thread.
>
Then we still add lock protection in the hook function, when trace is
disable ?
Or we also pass these to hook function, no matter the trace is enable or
not.I think this way is more clear that the lock protects @from,
@to_proc and @to_thread.Then, there is no need to add the lock in hook
function.
int from_proc, from_thread, to_proc, to_thread;
spin_lock(>lock);
from_proc = t->from ? t->from->proc->pid : 0;
from_thread = t->from ? t->from->pid :0;
to_proc = t->to_proc ? t->to_proc->pid : 0;
to_thread = t->to_thread ? t->to_thread->pid : 0;
spin_unlock(>lock);
trace_binder_txn_latency_free(t, from_proc, from_thread, to_proc,
to_pid);
> > binder_free_txn_fixups(t);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc
> > *proc,
> > kfree(tcomplete);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> > err_alloc_tcomplete_failed:
> > + spin_lock(>lock);
> > + trace_binder_txn_latency_free(t);
> > + spin_unlock(>lock);
> > kfree(t);
> > binder_stats_deleted(BINDER_STAT_TRANSACTION);
> > err_alloc_t_failed:
> > diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
> > index 6731c3c..8ac87d1 100644
> > --- a/drivers/android/binder_trace.h
> > +++ b/drivers/android/binder_trace.h
> > @@ -95,6 +95,33 @@
> > __entry->thread_todo)
> > );
> >
> > +TRACE_EVENT(binder_txn_latency_free,
> > + TP_PROTO(struct binder_transaction *t),
> > + TP_ARGS(t),
> > + TP_STRUCT__entry(
> > + __field(int, debug_id)
> > + __field(int, from_proc)
> > + __field(int, from_thread)
> > + __field(int, to_proc)
> > + __field(int, to_thread)
> > + __field(unsigned int, code)
> > + __field(unsigned int, flags)
> > + ),
> > + TP_fast_assign(
> > + __entry->debug_id = t->debug_id;
> > + __entry->from_proc = t->from ? t->from->proc->pid : 0;
> > + __entry->from_thread = t->from ? t->from->pid : 0;
> > + __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
> > + __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
> > + __entry->code = t->code;
> > + __entry->flags = t->flags;
> > + ),
> > + TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
> > + __entry->debug_id, __entry->from_proc,
> > __entry->from_thread,
> > + __entry->to_proc, __entry->to_thread, __entry->code,
> > + __entry->flags)
> > +);
> > +
> > TRACE_EVENT(binder_transaction,
> > TP_PROTO(bool reply, struct binder_transaction *t,
> > struct binder_node *target_node),
> > --
> > 1.7.9.5
Re: [PATCH v6 2/3] binder: add trace at free transaction.
On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
wrote:
>
> From: "Frankie.Chang"
>
> Since the original trace_binder_transaction_received cannot
> precisely present the real finished time of transaction, adding a
> trace_binder_txn_latency_free at the point of free transaction
> may be more close to it.
>
> Signed-off-by: Frankie.Chang
> ---
> drivers/android/binder.c |6 ++
> drivers/android/binder_trace.h | 27 +++
> 2 files changed, 33 insertions(+)
>
> diff --git a/drivers/android/binder.c b/drivers/android/binder.c
> index 2df146f..1e6fc40 100644
> --- a/drivers/android/binder.c
> +++ b/drivers/android/binder.c
> @@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct
> binder_transaction *t)
> * If the transaction has no target_proc, then
> * t->buffer->transaction has already been cleared.
> */
> + spin_lock(>lock);
> + trace_binder_txn_latency_free(t);
> + spin_unlock(>lock);
Hmm. I don't prefer taking the lock just to call a trace. It doesn't
make clear why the lock has to be taken. I'd prefer something like:
if (trace_binder_txn_latency_free_enabled()) {
int to_proc, to_thread;
spin_lock(>lock);
to_proc = t->to_proc ? t->to_proc->pid : 0;
to_thread = t->to_thread ? t->to_thread->pid : 0;
spin_unlock(>lock);
trace_binder_txn_latency_free(t, to_proc, to_pid);
}
And then the trace would use the passed-in values instead of accessing
via t->to_proc/to_thread.
> binder_free_txn_fixups(t);
> kfree(t);
> binder_stats_deleted(BINDER_STAT_TRANSACTION);
> @@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc *proc,
> kfree(tcomplete);
> binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
> err_alloc_tcomplete_failed:
> + spin_lock(>lock);
> + trace_binder_txn_latency_free(t);
> + spin_unlock(>lock);
> kfree(t);
> binder_stats_deleted(BINDER_STAT_TRANSACTION);
> err_alloc_t_failed:
> diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
> index 6731c3c..8ac87d1 100644
> --- a/drivers/android/binder_trace.h
> +++ b/drivers/android/binder_trace.h
> @@ -95,6 +95,33 @@
> __entry->thread_todo)
> );
>
> +TRACE_EVENT(binder_txn_latency_free,
> + TP_PROTO(struct binder_transaction *t),
> + TP_ARGS(t),
> + TP_STRUCT__entry(
> + __field(int, debug_id)
> + __field(int, from_proc)
> + __field(int, from_thread)
> + __field(int, to_proc)
> + __field(int, to_thread)
> + __field(unsigned int, code)
> + __field(unsigned int, flags)
> + ),
> + TP_fast_assign(
> + __entry->debug_id = t->debug_id;
> + __entry->from_proc = t->from ? t->from->proc->pid : 0;
> + __entry->from_thread = t->from ? t->from->pid : 0;
> + __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
> + __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
> + __entry->code = t->code;
> + __entry->flags = t->flags;
> + ),
> + TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
> + __entry->debug_id, __entry->from_proc, __entry->from_thread,
> + __entry->to_proc, __entry->to_thread, __entry->code,
> + __entry->flags)
> +);
> +
> TRACE_EVENT(binder_transaction,
> TP_PROTO(bool reply, struct binder_transaction *t,
> struct binder_node *target_node),
> --
> 1.7.9.5
[PATCH v6 2/3] binder: add trace at free transaction.
From: "Frankie.Chang"
Since the original trace_binder_transaction_received cannot
precisely present the real finished time of transaction, adding a
trace_binder_txn_latency_free at the point of free transaction
may be more close to it.
Signed-off-by: Frankie.Chang
---
drivers/android/binder.c |6 ++
drivers/android/binder_trace.h | 27 +++
2 files changed, 33 insertions(+)
diff --git a/drivers/android/binder.c b/drivers/android/binder.c
index 2df146f..1e6fc40 100644
--- a/drivers/android/binder.c
+++ b/drivers/android/binder.c
@@ -1522,6 +1522,9 @@ static void binder_free_transaction(struct
binder_transaction *t)
* If the transaction has no target_proc, then
* t->buffer->transaction has already been cleared.
*/
+ spin_lock(>lock);
+ trace_binder_txn_latency_free(t);
+ spin_unlock(>lock);
binder_free_txn_fixups(t);
kfree(t);
binder_stats_deleted(BINDER_STAT_TRANSACTION);
@@ -3093,6 +3096,9 @@ static void binder_transaction(struct binder_proc *proc,
kfree(tcomplete);
binder_stats_deleted(BINDER_STAT_TRANSACTION_COMPLETE);
err_alloc_tcomplete_failed:
+ spin_lock(>lock);
+ trace_binder_txn_latency_free(t);
+ spin_unlock(>lock);
kfree(t);
binder_stats_deleted(BINDER_STAT_TRANSACTION);
err_alloc_t_failed:
diff --git a/drivers/android/binder_trace.h b/drivers/android/binder_trace.h
index 6731c3c..8ac87d1 100644
--- a/drivers/android/binder_trace.h
+++ b/drivers/android/binder_trace.h
@@ -95,6 +95,33 @@
__entry->thread_todo)
);
+TRACE_EVENT(binder_txn_latency_free,
+ TP_PROTO(struct binder_transaction *t),
+ TP_ARGS(t),
+ TP_STRUCT__entry(
+ __field(int, debug_id)
+ __field(int, from_proc)
+ __field(int, from_thread)
+ __field(int, to_proc)
+ __field(int, to_thread)
+ __field(unsigned int, code)
+ __field(unsigned int, flags)
+ ),
+ TP_fast_assign(
+ __entry->debug_id = t->debug_id;
+ __entry->from_proc = t->from ? t->from->proc->pid : 0;
+ __entry->from_thread = t->from ? t->from->pid : 0;
+ __entry->to_proc = t->to_proc ? t->to_proc->pid : 0;
+ __entry->to_thread = t->to_thread ? t->to_thread->pid : 0;
+ __entry->code = t->code;
+ __entry->flags = t->flags;
+ ),
+ TP_printk("transaction=%d from %d:%d to %d:%d flags=0x%x code=0x%x",
+ __entry->debug_id, __entry->from_proc, __entry->from_thread,
+ __entry->to_proc, __entry->to_thread, __entry->code,
+ __entry->flags)
+);
+
TRACE_EVENT(binder_transaction,
TP_PROTO(bool reply, struct binder_transaction *t,
struct binder_node *target_node),
--
1.7.9.5
