| Message ID | 20190820230900.23445-4-peter@lekensteyn.nl |
|---|---|
| State | Accepted |
| Delegated to: | BPF Maintainers |
| Headers | show |
| Series | BPF-related documentation fixes | expand |
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.
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?
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
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
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(+)