Re: [PATCH] docs: ftrace: Specifies when buffers get clear

["Frank A. Cancio Bello" <frank@generalsoftwareinc.com>]

On Mon, Dec 16, 2019 at 09:52:51AM -0500, Steven Rostedt wrote:
> On Sun, 15 Dec 2019 23:27:56 -0500
> "Frank A. Cancio Bello" <frank@generalsoftwareinc.com> wrote:
> 
> > Clarify in a few places where the ring buffer and the "snapshot"
> > buffer are cleared as a side effect of an operation.
> > 
> > This will avoid users lost of tracing data because of these so far
> > undocumented behavior.
> > 
> > Signed-off-by: Frank A. Cancio Bello <frank@generalsoftwareinc.com>
> > ---
> >  Documentation/trace/ftrace.rst | 10 ++++++++--
> >  1 file changed, 8 insertions(+), 2 deletions(-)
> > 
> > diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst
> > index d2b5657ed33e..5cc65314e16d 100644
> > --- a/Documentation/trace/ftrace.rst
> > +++ b/Documentation/trace/ftrace.rst
> > @@ -95,7 +95,8 @@ of ftrace. Here is a list of some of the key files:
> >    current_tracer:
> >  
> >  	This is used to set or display the current tracer
> > -	that is configured.
> > +	that is configured. Changing the current tracer clears
> > +        the ring buffer content as well as the "snapshot" buffer.
> >  
> >    available_tracers:
> >  
> > @@ -126,7 +127,9 @@ of ftrace. Here is a list of some of the key files:
> >  	This file holds the output of the trace in a human
> >  	readable format (described below). Note, tracing is temporarily
> >  	disabled when the file is open for reading. Once all readers
> > -	are closed, tracing is re-enabled.
> > +	are closed, tracing is re-enabled. Opening this file for
> > +        writing with the O_TRUNC flag clears the ring buffer content
> > +        as well as the "snapshot" buffer.
> 
> Writing O_TRUNC into trace does not touch the snapshot buffer. I just
> tested to make sure (because that's not the behavior I remember making):
>

You are right. I should test it before email you. Sorry about that.
I miss read tracing_reset_all_online_cpus() when in reality it was
tracing_reset_online_cpus(), this kind of things happens to me when I
read kernel source code more than 12 hours per day to try to catchup ;)

vim-linux-coding-style does not include .rst files, so this patch has
the spacing wrong too, I fixed it in the v2 that I sent you too.

>  # cd /sys/kernel/tracing
>  # echo 1 > events/sched/enable
>  # echo 1 > snapshot
>  # head -15 snapshot  
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 3563/3563   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>             bash-20130 [007] d.h. 243924.135391: sched_stat_runtime: comm=bash pid=20130 runtime=584815 [ns] vruntime=116509213 [ns]
>             bash-20130 [007] d... 243924.135853: sched_waking: comm=kworker/u16:2 pid=20112 prio=120 target_cpu=002
>             bash-20130 [007] d... 243924.135859: sched_wake_idle_without_ipi: cpu=2
>             bash-20130 [007] d... 243924.135861: sched_wakeup: comm=kworker/u16:2 pid=20112 prio=120 target_cpu=002
>  # echo 0 > tracing_on
>  # head -15 trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 1697/1697   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>             sshd-20125 [005] d... 244126.123095: sched_stat_runtime: comm=sshd pid=20125 runtime=101555 [ns] vruntime=153686839 [ns]
>             sshd-20125 [005] d... 244126.123100: sched_switch: prev_comm=sshd prev_pid=20125 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
>             bash-20130 [007] d... 244126.123173: sched_waking: comm=kworker/u16:3 pid=20190 prio=120 target_cpu=006
>             bash-20130 [007] d... 244126.123177: sched_wake_idle_without_ipi: cpu=6
>  # echo > trace
>  # head -15 trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 0/0   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>  # head -15 snapshot
>  # tracer: nop
> #
> # entries-in-buffer/entries-written: 3563/3563   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>             bash-20130 [007] d.h. 243924.135391: sched_stat_runtime: comm=bash pid=20130 runtime=584815 [ns] vruntime=116509213 [ns]
>             bash-20130 [007] d... 243924.135853: sched_waking: comm=kworker/u16:2 pid=20112 prio=120 target_cpu=002
>             bash-20130 [007] d... 243924.135859: sched_wake_idle_without_ipi: cpu=2
>             bash-20130 [007] d... 243924.135861: sched_wakeup: comm=kworker/u16:2 pid=20112 prio=120 target_cpu=002
> 
> >  
> >    trace_pipe:
> >  
> > @@ -490,6 +493,9 @@ of ftrace. Here is a list of some of the key files:
> >  
> >  	  # echo global > trace_clock
> >  
> > +        Setting a clock clears the ring buffer content as well as the
> > +        "snapshot" buffer.
> > +
> 
> Yeah, this is true, because the sorting algorithm relies on the trace
> clocks matching in the buffers. If this becomes an issue, I'm sure we
> could change it.
> 

Besides, if the new clock is not in nanoseconds or "a clock at
all" (e.g. it is a counter) changing the clock it would produce an
inaccurate interpretation of the snapshot if we don't store the clock
that was used to fill the buffer that is in the snapshot. So, I think
that it is OK to reset the snapshot in this case. I just wanted to
document this behavior.

Thanks a lot for your quick response and sorry for my delay. I'm still
playing with email filters to properly accommodate the email flow of the
lists.

I want to congratulate you for such a nice piece of code you wrote:
ftrace. Being an Outreachy intern (mentors and co-interns CCed in this
email) and be able to learn so much from your code is a great
opportunity!

thanks
frank a.


> -- Steve
> 
> >    trace_marker:
> >  
> >  	This is a very useful file for synchronizing user space
>