[PATCH 0/4] [GIT PULL] tracing/ring-buffer: updates for tip

[PATCH 0/4] [GIT PULL] tracing/ring-buffer: updates for tip

[Steven Rostedt]

Ingo,

Please pull the latest tip/tracing/ftrace tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/ftrace


Steven Rostedt (4):
      tracing: have menu default enabled when kernel debug is configured
      ring-buffer: only periodically call cond_resched to ring-buffer-benchmark
      ring-buffer: add total count in ring-buffer-benchmark
      ring-buffer: change WARN_ON from checking preempt_count to preemptible

----
 kernel/trace/Kconfig                 |    1 +
 kernel/trace/ring_buffer.c           |    2 +-
 kernel/trace/ring_buffer_benchmark.c |   22 ++++++++++++++++++++--
 3 files changed, 22 insertions(+), 3 deletions(-)
-- 

[PATCH 1/4] tracing: have menu default enabled when kernel debug is configured

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-have-menu-default-enabled-when-kernel-debug.patch --]
[-- Type: text/plain, Size: 857 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Tracing can be very helpful to debug the kernel. When DEBUG_KERNEL is
enabled it is nice to enable the trace menu as well.

This patch only make the tracing menu enabled by default, it does not
make any of the tracers enabled. And the menu is only enabled by
default if DEBUG_KERNEL is enabled.

[ Impact: show tracing options to those debugging the kernel ]

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/Kconfig |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 50f62a2..f61be30 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -79,6 +79,7 @@ if TRACING_SUPPORT
 
 menuconfig FTRACE
 	bool "Tracers"
+	default y if DEBUG_KERNEL
 	help
 	 Enable the kernel tracing infrastructure.
 
-- 
1.6.2.4

-- 

[PATCH 2/4] ring-buffer: only periodically call cond_resched to ring-buffer-benchmark

[Steven Rostedt]

[-- Attachment #1: 0002-ring-buffer-only-periodically-call-cond_resched-to.patch --]
[-- Type: text/plain, Size: 1483 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

Calling cond_resched at every iteration of the loop adds a bit of
overhead to the benchmark.

This patch does two things.

1) only calls cond-resched when CONFIG_PREEMPT is not enabled
2) only calls cond-resched after so many traces has been performed.

[ Impact: less overhead to the ring-buffer-benchmark ]

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer_benchmark.c |   11 +++++++++--
 1 files changed, 9 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ring_buffer_benchmark.c b/kernel/trace/ring_buffer_benchmark.c
index f4ceb45..a7c048b 100644
--- a/kernel/trace/ring_buffer_benchmark.c
+++ b/kernel/trace/ring_buffer_benchmark.c
@@ -218,16 +218,23 @@ static void ring_buffer_producer(void)
 		}
 		do_gettimeofday(&end_tv);
 
-		if (consumer && !(++cnt % wakeup_interval))
+		cnt++;
+		if (consumer && !(cnt % wakeup_interval))
 			wake_up_process(consumer);
 
+#ifndef CONFIG_PREEMPT
 		/*
 		 * If we are a non preempt kernel, the 10 second run will
 		 * stop everything while it runs. Instead, we will call
 		 * cond_resched and also add any time that was lost by a
 		 * rescedule.
+		 *
+		 * Do a cond resched at the same frequency we would wake up
+		 * the reader.
 		 */
-		cond_resched();
+		if (cnt % wakeup_interval)
+			cond_resched();
+#endif
 
 	} while (end_tv.tv_sec < (start_tv.tv_sec + RUN_TIME) && !kill_test);
 	pr_info("End ring buffer hammer\n");
-- 
1.6.2.4

-- 

[PATCH 3/4] ring-buffer: add total count in ring-buffer-benchmark

[Steven Rostedt]

[-- Attachment #1: 0003-ring-buffer-add-total-count-in-ring-buffer-benchmar.patch --]
[-- Type: text/plain, Size: 1257 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

It is nice to see the overhead of the benchmark test when tracing is
disabled. That is, we turn off the ring buffer just to see what the
cost of running the loop that calls into the ring buffer is.

Currently, if no entries wer made, we get 0. This is not informative.
This patch changes it to check if we had any "missed" (non recorded)
events. If so, a total count is also reported.

[ Impact: evaluate the over head of the ring buffer benchmark test ]

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer_benchmark.c |   11 +++++++++++
 1 files changed, 11 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ring_buffer_benchmark.c b/kernel/trace/ring_buffer_benchmark.c
index a7c048b..a21aa7b 100644
--- a/kernel/trace/ring_buffer_benchmark.c
+++ b/kernel/trace/ring_buffer_benchmark.c
@@ -285,6 +285,17 @@ static void ring_buffer_producer(void)
 		avg = 1000000 / hit;
 		pr_info("%ld ns per entry\n", avg);
 	}
+
+
+	if (missed) {
+		if (time)
+			missed /= (long)time;
+
+		pr_info("Total iterations per millisec: %ld\n", hit + missed);
+
+		avg = 1000000 / (hit + missed);
+		pr_info("%ld ns per entry\n", avg);
+	}
 }
 
 static void wait_to_die(void)
-- 
1.6.2.4

-- 

Re: [PATCH 3/4] ring-buffer: add total count in ring-buffer-benchmark

[Andrew Morton]

On Fri, 08 May 2009 00:32:53 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:

> --- a/kernel/trace/ring_buffer_benchmark.c
> +++ b/kernel/trace/ring_buffer_benchmark.c
> @@ -285,6 +285,17 @@ static void ring_buffer_producer(void)
>  		avg = 1000000 / hit;
>  		pr_info("%ld ns per entry\n", avg);
>  	}
> +
> +

s/\n\n/\n/

> +	if (missed) {
> +		if (time)
> +			missed /= (long)time;
> +
> +		pr_info("Total iterations per millisec: %ld\n", hit + missed);
> +
> +		avg = 1000000 / (hit + missed);

s/1000000/USEC_PER_SEC/?

Hopefully we can't have hit+missed==0.

They're counters and hence should have unsigned types.

But even unsigned up-counters can add to zero if wrapping occurs.


> +		pr_info("%ld ns per entry\n", avg);
> +	}
>  }

Re: [PATCH 3/4] ring-buffer: add total count in ring-buffer-benchmark

[Steven Rostedt]

On Thu, 7 May 2009, Andrew Morton wrote:

> On Fri, 08 May 2009 00:32:53 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > --- a/kernel/trace/ring_buffer_benchmark.c
> > +++ b/kernel/trace/ring_buffer_benchmark.c
> > @@ -285,6 +285,17 @@ static void ring_buffer_producer(void)
> >  		avg = 1000000 / hit;
> >  		pr_info("%ld ns per entry\n", avg);
> >  	}
> > +
> > +
> 
> s/\n\n/\n/

My pinky must hae been itchy, and hit the enter twice.

> 
> > +	if (missed) {
> > +		if (time)
> > +			missed /= (long)time;
> > +
> > +		pr_info("Total iterations per millisec: %ld\n", hit + missed);
> > +
> > +		avg = 1000000 / (hit + missed);
> 
> s/1000000/USEC_PER_SEC/?

Heh, after I sent out the patch, I noticed that number, and thought to 
myself, "oh no, akpm is going to commont on that" ;-)

> 
> Hopefully we can't have hit+missed==0.
> 
> They're counters and hence should have unsigned types.
> 
> But even unsigned up-counters can add to zero if wrapping occurs.

Eigad! I never thought about an overflow to zero. Will fix.

Thanks!

-- Steve

> 
> 
> > +		pr_info("%ld ns per entry\n", avg);
> > +	}
> >  }
> 

[PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Steven Rostedt]

[-- Attachment #1: 0004-ring-buffer-change-WARN_ON-from-checking-preempt_co.patch --]
[-- Type: text/plain, Size: 964 bytes --]

From: Steven Rostedt <srostedt@redhat.com>

There's a WARN_ON in the ring buffer code that makes sure preemption
is disabled. It checks "!preempt_count()". But when CONFIG_PREEMPT is not
enabled, preempt_count() is always zero, and this will trigger the warning.

[ Impact: prevent false warning on non preemptible kernels ]

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ring_buffer.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 3ae5ccf..3611706 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
 	 * committed yet. Thus we can assume that preemption
 	 * is still disabled.
 	 */
-	RB_WARN_ON(buffer, !preempt_count());
+	RB_WARN_ON(buffer, preemptible());
 
 	cpu = smp_processor_id();
 	cpu_buffer = buffer->buffers[cpu];
-- 
1.6.2.4

-- 

Re: [PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Andrew Morton]

On Fri, 08 May 2009 00:32:54 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Steven Rostedt <srostedt@redhat.com>
> 
> There's a WARN_ON in the ring buffer code that makes sure preemption
> is disabled. It checks "!preempt_count()". But when CONFIG_PREEMPT is not
> enabled, preempt_count() is always zero, and this will trigger the warning.
> 
> [ Impact: prevent false warning on non preemptible kernels ]
> 
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  kernel/trace/ring_buffer.c |    2 +-
>  1 files changed, 1 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index 3ae5ccf..3611706 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
>  	 * committed yet. Thus we can assume that preemption
>  	 * is still disabled.
>  	 */
> -	RB_WARN_ON(buffer, !preempt_count());
> +	RB_WARN_ON(buffer, preemptible());
>  
>  	cpu = smp_processor_id();
>  	cpu_buffer = buffer->buffers[cpu];

smp_processor_id() will warn too.

Re: [PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Steven Rostedt]

On Thu, 7 May 2009, Andrew Morton wrote:

> On Fri, 08 May 2009 00:32:54 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > From: Steven Rostedt <srostedt@redhat.com>
> > 
> > There's a WARN_ON in the ring buffer code that makes sure preemption
> > is disabled. It checks "!preempt_count()". But when CONFIG_PREEMPT is not
> > enabled, preempt_count() is always zero, and this will trigger the warning.
> > 
> > [ Impact: prevent false warning on non preemptible kernels ]
> > 
> > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > ---
> >  kernel/trace/ring_buffer.c |    2 +-
> >  1 files changed, 1 insertions(+), 1 deletions(-)
> > 
> > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > index 3ae5ccf..3611706 100644
> > --- a/kernel/trace/ring_buffer.c
> > +++ b/kernel/trace/ring_buffer.c
> > @@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
> >  	 * committed yet. Thus we can assume that preemption
> >  	 * is still disabled.
> >  	 */
> > -	RB_WARN_ON(buffer, !preempt_count());
> > +	RB_WARN_ON(buffer, preemptible());
> >  
> >  	cpu = smp_processor_id();
> >  	cpu_buffer = buffer->buffers[cpu];
> 
> smp_processor_id() will warn too.
> 

The difference is that RB_WARN_ON also disables the ring buffer.

-- Steve

Re: [PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> 
> On Thu, 7 May 2009, Andrew Morton wrote:
> 
> > On Fri, 08 May 2009 00:32:54 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > From: Steven Rostedt <srostedt@redhat.com>
> > > 
> > > There's a WARN_ON in the ring buffer code that makes sure preemption
> > > is disabled. It checks "!preempt_count()". But when CONFIG_PREEMPT is not
> > > enabled, preempt_count() is always zero, and this will trigger the warning.
> > > 
> > > [ Impact: prevent false warning on non preemptible kernels ]
> > > 
> > > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > > ---
> > >  kernel/trace/ring_buffer.c |    2 +-
> > >  1 files changed, 1 insertions(+), 1 deletions(-)
> > > 
> > > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > > index 3ae5ccf..3611706 100644
> > > --- a/kernel/trace/ring_buffer.c
> > > +++ b/kernel/trace/ring_buffer.c
> > > @@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
> > >  	 * committed yet. Thus we can assume that preemption
> > >  	 * is still disabled.
> > >  	 */
> > > -	RB_WARN_ON(buffer, !preempt_count());
> > > +	RB_WARN_ON(buffer, preemptible());
> > >  
> > >  	cpu = smp_processor_id();
> > >  	cpu_buffer = buffer->buffers[cpu];
> > 
> > smp_processor_id() will warn too.
> > 
> 
> The difference is that RB_WARN_ON also disables the ring buffer.

Yes, it's a more robust form of warning, in this context.

	Ingo

Re: [PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Andrew Morton]

On Fri, 8 May 2009 06:53:48 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> 
> On Thu, 7 May 2009, Andrew Morton wrote:
> 
> > On Fri, 08 May 2009 00:32:54 -0400 Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > From: Steven Rostedt <srostedt@redhat.com>
> > > 
> > > There's a WARN_ON in the ring buffer code that makes sure preemption
> > > is disabled. It checks "!preempt_count()". But when CONFIG_PREEMPT is not
> > > enabled, preempt_count() is always zero, and this will trigger the warning.
> > > 
> > > [ Impact: prevent false warning on non preemptible kernels ]
> > > 
> > > Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > > ---
> > >  kernel/trace/ring_buffer.c |    2 +-
> > >  1 files changed, 1 insertions(+), 1 deletions(-)
> > > 
> > > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > > index 3ae5ccf..3611706 100644
> > > --- a/kernel/trace/ring_buffer.c
> > > +++ b/kernel/trace/ring_buffer.c
> > > @@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
> > >  	 * committed yet. Thus we can assume that preemption
> > >  	 * is still disabled.
> > >  	 */
> > > -	RB_WARN_ON(buffer, !preempt_count());
> > > +	RB_WARN_ON(buffer, preemptible());
> > >  
> > >  	cpu = smp_processor_id();
> > >  	cpu_buffer = buffer->buffers[cpu];
> > 
> > smp_processor_id() will warn too.
> > 
> 
> The difference is that RB_WARN_ON also disables the ring buffer.
> 

Yes, but the kernel will produce two large warning spews for the
same thing.

Re: [PATCH 4/4] ring-buffer: change WARN_ON from checking preempt_count to preemptible

[Steven Rostedt]

On Fri, 8 May 2009, Andrew Morton wrote:

> On Fri, 8 May 2009 06:53:48 -0400 (EDT) Steven Rostedt <rostedt@goodmis.org> wrote:
> > > > 
> > > > diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> > > > index 3ae5ccf..3611706 100644
> > > > --- a/kernel/trace/ring_buffer.c
> > > > +++ b/kernel/trace/ring_buffer.c
> > > > @@ -1688,7 +1688,7 @@ void ring_buffer_discard_commit(struct ring_buffer *buffer,
> > > >  	 * committed yet. Thus we can assume that preemption
> > > >  	 * is still disabled.
> > > >  	 */
> > > > -	RB_WARN_ON(buffer, !preempt_count());
> > > > +	RB_WARN_ON(buffer, preemptible());
> > > >  
> > > >  	cpu = smp_processor_id();
> > > >  	cpu_buffer = buffer->buffers[cpu];
> > > 
> > > smp_processor_id() will warn too.
> > > 
> > 
> > The difference is that RB_WARN_ON also disables the ring buffer.
> > 
> 
> Yes, but the kernel will produce two large warning spews for the
> same thing.

Hmm, I should go back to my original patch. Which was:

	RB_WARN_ON_PREEMPT(buffer, !preempt_count());

and have at the top of the file:

#ifdef CONFIG_PREEMPT
# RB_WARN_ON_PREEMPT(buffer, cond)  RB_WARN_ON(buffer, cond)
#else
# RB_WARN_ON_PREEMPT(buffer, cond)  do { } while (0)
#endif

The difference here is not that preemption must be off, but that this must 
be called from after a ring_buffer_lock_reserve() but not after a 
ring_buffer_unlock_commit().

We have two methods to discard a change, one is to discard it instead of 
commiting it. This will try to totally remove the change without leaving 
holes. The ring buffer is reentrant, and if an interrupt were to happen 
in between reserve and commit, it could store data after this commit. In 
which case we have no choice but to leave a hole. But if that did not 
happen, then we use cmpxchg to reset the tail of the buffer back to the 
original and not have to worry about NMIs and interrupts.

The other version of discarding can be done after a commit. But it only 
changes the type of the data and a hole exits. If we did this for all 
discards, the ring buffer would be wasted with discarded material and the 
filtering would be useless.

The original code only had the discard with a hole, and that was done 
after the commit. After converting it over, to the new method, several 
places still had the discard after the commit, and that broke the ring 
buffer.

There's no easy way to catch this, and do it fast. Since preemption is 
always disabled between reserve and commit, I was able to find places that 
broke this (and even new places that were added) by simply checking if 
preemption is disabled. Note, preemptible() is actually wrong because it 
also checks if interrupts are disabled, and if interrupts are disabled but 
preemption is not, we miss the case as well.

In any case, if this happens then the ring buffer will be corrupted, and 
it is best to disable it. Having two big warnings will help have these 
errors stick out more :-)

Actually, the way I've noticed it (when it happened on my laptop) was when 
I ran the trace and got no output. Then I decided to do a dmesg to see 
why. If I just saw garbage (or even worse, a crash) then I would not have 
looked right away at the dmesg. A crash would have prevented me from 
looking at dmesg if it locked up my laptop.

-- Steve

Re: [PATCH 0/4] [GIT PULL] tracing/ring-buffer: updates for tip

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> Ingo,
> 
> Please pull the latest tip/tracing/ftrace tree, which can be found at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/ftrace
> 
> 
> Steven Rostedt (4):
>       tracing: have menu default enabled when kernel debug is configured
>       ring-buffer: only periodically call cond_resched to ring-buffer-benchmark
>       ring-buffer: add total count in ring-buffer-benchmark
>       ring-buffer: change WARN_ON from checking preempt_count to preemptible
> 
> ----
>  kernel/trace/Kconfig                 |    1 +
>  kernel/trace/ring_buffer.c           |    2 +-
>  kernel/trace/ring_buffer_benchmark.c |   22 ++++++++++++++++++++--
>  3 files changed, 22 insertions(+), 3 deletions(-)
> -- 

Pulled, thanks Steve. (I suspect i'll get the fix for the things 
noticed by Andrew in the next pull request?)

	Ingo