[PATCH] tracing: Resets the trace buffer after a snapshot

[PATCH] tracing: Resets the trace buffer after a snapshot

[Frank A. Cancio Bello]

Currently, when a snapshot is taken the trace_buffer and the
max_buffer are swapped. After this swap, the "new" trace_buffer is
not reset. This produces an odd behavior: after a snapshot is taken
the previous snapshot entries become available to the next reader of
the trace_buffer as far as the reading occurs before the buffer is
refilled with new entries by a writer.

This patch resets the trace buffer after a snapshot is taken.

Signed-off-by: Frank A. Cancio Bello <frank@generalsoftwareinc.com>
---

The following commands illustrate this odd behavior:

# cd /sys/kernel/debug/tracing
# echo nop > current_tracer
# echo 1 > tracing_on
# echo m1 > trace_marker
# echo 1 > snapshot
# echo m2 > trace_marker
# echo 1 > snapshot
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:2
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
            bash-550   [000] ....    50.479755: tracing_mark_write: m1


 kernel/trace/trace.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ddb7e7f5fe8d..58373b5ae0cf 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6867,10 +6867,13 @@ tracing_snapshot_write(struct file *filp, const char __user *ubuf, size_t cnt,
 			break;
 		local_irq_disable();
 		/* Now, we're going to swap */
-		if (iter->cpu_file == RING_BUFFER_ALL_CPUS)
+		if (iter->cpu_file == RING_BUFFER_ALL_CPUS) {
 			update_max_tr(tr, current, smp_processor_id(), NULL);
-		else
+			tracing_reset_online_cpus(&tr->trace_buffer);
+		} else {
 			update_max_tr_single(tr, current, iter->cpu_file);
+			tracing_reset_cpu(&tr->trace_buffer, iter->cpu_file);
+		}
 		local_irq_enable();
 		break;
 	default:
-- 
2.17.1

Re: [PATCH] tracing: Resets the trace buffer after a snapshot

[Steven Rostedt]

On Tue, 31 Dec 2019 03:58:22 -0500
"Frank A. Cancio Bello" <frank@generalsoftwareinc.com> wrote:

> Currently, when a snapshot is taken the trace_buffer and the
> max_buffer are swapped. After this swap, the "new" trace_buffer is
> not reset. This produces an odd behavior: after a snapshot is taken
> the previous snapshot entries become available to the next reader of
> the trace_buffer as far as the reading occurs before the buffer is
> refilled with new entries by a writer.

I consider this a feature not a bug ;-)

Anyway, this behavior should be determined by an option. Care to create
one? (reset_on_snapshot?) I would keep the default behavior the same,
but document this a bit better.

Thanks!

-- Steve

> 
> This patch resets the trace buffer after a snapshot is taken.
> 
> Signed-off-by: Frank A. Cancio Bello <frank@generalsoftwareinc.com>
> ---
> 
> The following commands illustrate this odd behavior:
> 
> # cd /sys/kernel/debug/tracing
> # echo nop > current_tracer
> # echo 1 > tracing_on
> # echo m1 > trace_marker
> # echo 1 > snapshot
> # echo m2 > trace_marker
> # echo 1 > snapshot
> # cat trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 1/1   #P:2
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>             bash-550   [000] ....    50.479755: tracing_mark_write: m1
> 
> 
>  kernel/trace/trace.c | 7 +++++--
>  1 file changed, 5 insertions(+), 2 deletions(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index ddb7e7f5fe8d..58373b5ae0cf 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -6867,10 +6867,13 @@ tracing_snapshot_write(struct file *filp, const char __user *ubuf, size_t cnt,
>  			break;
>  		local_irq_disable();
>  		/* Now, we're going to swap */
> -		if (iter->cpu_file == RING_BUFFER_ALL_CPUS)
> +		if (iter->cpu_file == RING_BUFFER_ALL_CPUS) {
>  			update_max_tr(tr, current, smp_processor_id(), NULL);
> -		else
> +			tracing_reset_online_cpus(&tr->trace_buffer);
> +		} else {
>  			update_max_tr_single(tr, current, iter->cpu_file);
> +			tracing_reset_cpu(&tr->trace_buffer, iter->cpu_file);
> +		}
>  		local_irq_enable();
>  		break;
>  	default:

Re: [PATCH] tracing: Resets the trace buffer after a snapshot

[Joel Fernandes]

On Fri, Jan 03, 2020 at 11:40:01AM -0500, Steven Rostedt wrote:
> On Tue, 31 Dec 2019 03:58:22 -0500
> "Frank A. Cancio Bello" <frank@generalsoftwareinc.com> wrote:
> 
> > Currently, when a snapshot is taken the trace_buffer and the
> > max_buffer are swapped. After this swap, the "new" trace_buffer is
> > not reset. This produces an odd behavior: after a snapshot is taken
> > the previous snapshot entries become available to the next reader of
> > the trace_buffer as far as the reading occurs before the buffer is
> > refilled with new entries by a writer.
> 
> I consider this a feature not a bug ;-)
> 
> Anyway, this behavior should be determined by an option. Care to create
> one? (reset_on_snapshot?) I would keep the default behavior the same,
> but document this a bit better.

I relate to what Steve said as well. It is not strictly a bug per-se. An
option to do this would be nice but I am doubting a user will really turn on
such option (or even know an option exists) ;-). I would say leave it in the
current state unless some usecase is disrupted by the current behavior..

thanks!

 - Joel


> 
> Thanks!
> 
> -- Steve
> 
> > 
> > This patch resets the trace buffer after a snapshot is taken.
> > 
> > Signed-off-by: Frank A. Cancio Bello <frank@generalsoftwareinc.com>
> > ---
> > 
> > The following commands illustrate this odd behavior:
> > 
> > # cd /sys/kernel/debug/tracing
> > # echo nop > current_tracer
> > # echo 1 > tracing_on
> > # echo m1 > trace_marker
> > # echo 1 > snapshot
> > # echo m2 > trace_marker
> > # echo 1 > snapshot
> > # cat trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 1/1   #P:2
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >             bash-550   [000] ....    50.479755: tracing_mark_write: m1
> > 
> > 
> >  kernel/trace/trace.c | 7 +++++--
> >  1 file changed, 5 insertions(+), 2 deletions(-)
> > 
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index ddb7e7f5fe8d..58373b5ae0cf 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -6867,10 +6867,13 @@ tracing_snapshot_write(struct file *filp, const char __user *ubuf, size_t cnt,
> >  			break;
> >  		local_irq_disable();
> >  		/* Now, we're going to swap */
> > -		if (iter->cpu_file == RING_BUFFER_ALL_CPUS)
> > +		if (iter->cpu_file == RING_BUFFER_ALL_CPUS) {
> >  			update_max_tr(tr, current, smp_processor_id(), NULL);
> > -		else
> > +			tracing_reset_online_cpus(&tr->trace_buffer);
> > +		} else {
> >  			update_max_tr_single(tr, current, iter->cpu_file);
> > +			tracing_reset_cpu(&tr->trace_buffer, iter->cpu_file);
> > +		}
> >  		local_irq_enable();
> >  		break;
> >  	default:
> 

Re: [PATCH] tracing: Resets the trace buffer after a snapshot

[Frank A. Cancio Bello]

On Fri, Jan 03, 2020 at 05:37:11PM -0500, Joel Fernandes wrote:
> On Fri, Jan 03, 2020 at 11:40:01AM -0500, Steven Rostedt wrote:
> > On Tue, 31 Dec 2019 03:58:22 -0500
> > "Frank A. Cancio Bello" <frank@generalsoftwareinc.com> wrote:
> > 
> > > Currently, when a snapshot is taken the trace_buffer and the
> > > max_buffer are swapped. After this swap, the "new" trace_buffer is
> > > not reset. This produces an odd behavior: after a snapshot is taken
> > > the previous snapshot entries become available to the next reader of
> > > the trace_buffer as far as the reading occurs before the buffer is
> > > refilled with new entries by a writer.
> > 
> > I consider this a feature not a bug ;-)
> > 
> > Anyway, this behavior should be determined by an option. Care to create
> > one? (reset_on_snapshot?) I would keep the default behavior the same,
> > but document this a bit better.
> 
> I relate to what Steve said as well. It is not strictly a bug per-se. An
> option to do this would be nice but I am doubting a user will really turn on
> such option (or even know an option exists) ;-). I would say leave it in the
> current state unless some usecase is disrupted by the current behavior..
> 

Thank you both for your answers. I'm wondering what would be the reason
for not resetting the trace buffer after it gets swapped with the snapshot
buffer. Given that resetting it's not expensive, I would say that is not
performance, so I'm intrigued ;)

If it's OK, I will send two patches then, one documenting explicitly
that the trace buffer it will not be reset after be swapped and the
implications of this, and the second one changing the documentation of
the field trace_array->max_buffer that I now realized that say:

"
/*
...
* The buffers for the max_buffer are set up the same as the trace_buffer
* When a snapshot is taken, the buffer of the max_buffer is swapped
* with the buffer of the trace_buffer and the buffers are reset for
* the trace_buffer so the tracing can continue.
*/

thanks
frank a.

> thanks!
> 
>  - Joel
> 
> 
> > 
> > Thanks!
> > 
> > -- Steve
> > 
> > > 
> > > This patch resets the trace buffer after a snapshot is taken.
> > > 
> > > Signed-off-by: Frank A. Cancio Bello <frank@generalsoftwareinc.com>
> > > ---
> > > 
> > > The following commands illustrate this odd behavior:
> > > 
> > > # cd /sys/kernel/debug/tracing
> > > # echo nop > current_tracer
> > > # echo 1 > tracing_on
> > > # echo m1 > trace_marker
> > > # echo 1 > snapshot
> > > # echo m2 > trace_marker
> > > # echo 1 > snapshot
> > > # cat trace
> > > # tracer: nop
> > > #
> > > # entries-in-buffer/entries-written: 1/1   #P:2
> > > #
> > > #                              _-----=> irqs-off
> > > #                             / _----=> need-resched
> > > #                            | / _---=> hardirq/softirq
> > > #                            || / _--=> preempt-depth
> > > #                            ||| /     delay
> > > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > > #              | |       |   ||||       |         |
> > >             bash-550   [000] ....    50.479755: tracing_mark_write: m1
> > > 
> > > 
> > >  kernel/trace/trace.c | 7 +++++--
> > >  1 file changed, 5 insertions(+), 2 deletions(-)
> > > 
> > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > > index ddb7e7f5fe8d..58373b5ae0cf 100644
> > > --- a/kernel/trace/trace.c
> > > +++ b/kernel/trace/trace.c
> > > @@ -6867,10 +6867,13 @@ tracing_snapshot_write(struct file *filp, const char __user *ubuf, size_t cnt,
> > >  			break;
> > >  		local_irq_disable();
> > >  		/* Now, we're going to swap */
> > > -		if (iter->cpu_file == RING_BUFFER_ALL_CPUS)
> > > +		if (iter->cpu_file == RING_BUFFER_ALL_CPUS) {
> > >  			update_max_tr(tr, current, smp_processor_id(), NULL);
> > > -		else
> > > +			tracing_reset_online_cpus(&tr->trace_buffer);
> > > +		} else {
> > >  			update_max_tr_single(tr, current, iter->cpu_file);
> > > +			tracing_reset_cpu(&tr->trace_buffer, iter->cpu_file);
> > > +		}
> > >  		local_irq_enable();
> > >  		break;
> > >  	default:
> > 

Re: [PATCH] tracing: Resets the trace buffer after a snapshot

[Steven Rostedt]

On Sun, 5 Jan 2020 05:31:13 -0500
"Frank A. Cancio Bello" <frank@generalsoftwareinc.com> wrote:

> 
> Thank you both for your answers. I'm wondering what would be the reason
> for not resetting the trace buffer after it gets swapped with the snapshot
> buffer. Given that resetting it's not expensive, I would say that is not
> performance, so I'm intrigued ;)

Is it not expensive? It calls synchronize_rcu()! which is very
expensive.

When I have used the snapshot buffer, It was usually to capture things
that happen at various times, but still look for the next trace. By
alternating, I do get to see where the last snapshot happened. It
basically doubles the size of the buffer.

> 
> If it's OK, I will send two patches then, one documenting explicitly
> that the trace buffer it will not be reset after be swapped and the
> implications of this, and the second one changing the documentation of
> the field trace_array->max_buffer that I now realized that say:
> 
> "
> /*
> ...
> * The buffers for the max_buffer are set up the same as the trace_buffer
> * When a snapshot is taken, the buffer of the max_buffer is swapped
> * with the buffer of the trace_buffer and the buffers are reset for
> * the trace_buffer so the tracing can continue.

It is reset partially by the latency tracers, and this is where it gets
confusing. Instead of a full reset, as the latency tracer only cares
about a specific start and end, it records where the start and end is,
and only modifies that. Look at the time_start of the trace_buffer.

Hmm, it may be possible to have an option just update that, which
should give the same effect.

-- Steve