Re: [PATCH v2 3/4] bpf: clarify when bpf_trace_printk discards lines

[Peter Wu <peter@lekensteyn.nl>]

On Tue, Aug 20, 2019 at 04:22:23PM -0700, Alexei Starovoitov wrote:
> On Wed, Aug 21, 2019 at 12:08:59AM +0100, Peter Wu wrote:
> > I opened /sys/kernel/tracing/trace once and kept reading from it.
> > bpf_trace_printk somehow did not seem to work, no entries were appended
> > to that trace file. It turns out that tracing is disabled when that file
> > is open. Save the next person some time and document this.
> > 
> > The trace file is described in Documentation/trace/ftrace.rst, however
> > the implication "tracing is disabled" did not immediate translate to
> > "bpf_trace_printk silently discards entries".
> > 
> > Signed-off-by: Peter Wu <peter@lekensteyn.nl>
> > ---
> >  include/uapi/linux/bpf.h | 2 ++
> >  1 file changed, 2 insertions(+)
> > 
> > diff --git a/include/uapi/linux/bpf.h b/include/uapi/linux/bpf.h
> > index 9ca333c3ce91..e4236e357ed9 100644
> > --- a/include/uapi/linux/bpf.h
> > +++ b/include/uapi/linux/bpf.h
> > @@ -575,6 +575,8 @@ union bpf_attr {
> >   * 		limited to five).
> >   *
> >   * 		Each time the helper is called, it appends a line to the trace.
> > + * 		Lines are discarded while *\/sys/kernel/debug/tracing/trace* is
> > + * 		open, use *\/sys/kernel/debug/tracing/trace_pipe* to avoid this.
> 
> that's not quite correct.
> Having 'trace' file open doesn't discard lines.
> I think this type of comment in uapi header makes more confusion than helps.

Having the 'trace' file open for reading results in discarding lines. It
took me a while to figure that out. At first I was not even sure whether
my eBPF program was executed or not due to lack of entries in the
'trace' file.

I ended up setting a breakpoint and ended up with this call stack:

  - bpf_trace_printk
    - ____bpf_trace_printk
      - __trace_printk
        - trace_vprintk
          - trace_array_vprintk
            - __trace_array_vprintk
              - __trace_array_vprintk
                - __trace_buffer_lock_reserve
                  - ring_buffer_lock_reserve

The function ends up skipping the even because record_disabled == 1:

    if (unlikely(atomic_read(&buffer->record_disabled)))
        goto out;

Why is that? Well, I guessed that ring_buffer_record_disable and
ring_buffer_record_enable would be related. Sure enough, the first one
was hit when the 'trace' file is opened for reading while the latter is
called when the file is closed.

The relevant code from kernel/trace/trace.c (__tracing_open), "snapshot"
is true when "trace" is opened, and "false" when "trace_pipe" is used:

    /* stop the trace while dumping if we are not opening "snapshot" */
    if (!iter->snapshot)
        tracing_stop_tr(tr);

So I think this supports the claim that lines are discarded. Do you
think this is not the case?
-- 
Kind regards,
Peter Wu
https://lekensteyn.nl