[v2,3/4] bpf: clarify when bpf_trace_printk discards lines
diff mbox series

Message ID 20190820230900.23445-4-peter@lekensteyn.nl
State Accepted
Delegated to: BPF Maintainers
Headers show
Series
  • BPF-related documentation fixes
Related show

Commit Message

Peter Wu Aug. 20, 2019, 11:08 p.m. UTC
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(+)

Comments

Alexei Starovoitov Aug. 20, 2019, 11:22 p.m. UTC | #1
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.
Peter Wu Aug. 21, 2019, 12:04 a.m. UTC | #2
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?
Alexei Starovoitov Aug. 21, 2019, 5:23 p.m. UTC | #3
On Tue, Aug 20, 2019 at 5:04 PM Peter Wu <peter@lekensteyn.nl> wrote:
>
> 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?

Indeed.
I missed "(opened)" part in Documentation/trace/ftrace.rst:
  trace:
        This file holds the output of the trace in a human
        readable format (described below). Note, tracing is temporarily
        disabled while this file is being read (opened).

I always thought that reading disables it.
It's indeed odd part of the ftrace implementation that
worth documenting here.

Applied the set to bpf-next. Thanks

Patch
diff mbox series

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.
  * 		The format of the trace is customizable, and the exact output
  * 		one will get depends on the options set in
  * 		*\/sys/kernel/debug/tracing/trace_options* (see also the