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

[Todd Kjos <tkjos@google.com>]

On Sun, Aug 2, 2020 at 8:11 PM Frankie Chang <Frankie.Chang@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@mediatek.com> wrote:
> > >
> > > From: "Frankie.Chang" <Frankie.Chang@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@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.

> 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(&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.

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