On Tue, Aug 20, 2019 at 5:04 PM Peter Wu <peter@xxxxxxxxxxxxx> 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@xxxxxxxxxxxxx>
> > > ---
> > > 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
