[PATCH v6 2/3] binder: add trace at free transaction.

[Frankie Chang]

On Mon, 2020-08-03 at 08:12 -0700, Todd Kjos wrote:
> On Sun, Aug 2, 2020 at 8:11 PM Frankie Chang <Frankie.Chang at mediatek.com> wrote:
> >
> > On Fri, 2020-07-31 at 11:50 -0700, Todd Kjos wrote:
> > > On Mon, Jul 27, 2020 at 8:28 PM Frankie Chang
> > > <Frankie.Chang at mediatek.com> wrote:
> > > >
> > > > From: "Frankie.Chang" <Frankie.Chang at mediatek.com>
> > > >
> > > > 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 <Frankie.Chang at mediatek.com>
> > > > ---
> > > >  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(&t->lock);
> > > > +       trace_binder_txn_latency_free(t);
> > > > +       spin_unlock(&t->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(&t->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(&t->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(&t->lock);
> > > > +       trace_binder_txn_latency_free(t);
> > > > +       spin_unlock(&t->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
> >