[PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Frederic Weisbecker]

Impact: prevent a trace recursion

After some tests with function graph tracer under x86-32, I saw some recursions
caused by ring_buffer_time_stamp() that calls preempt_enable_no_notrace() which
calls preempt_schedule() which is traced itself.

This patch re-enables preemption without rescheduling.

Cc: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 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 822fcd4..a775e46 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -109,7 +109,7 @@ u64 ring_buffer_time_stamp(int cpu)
 	preempt_disable_notrace();
 	/* shift to debug/test normalization and TIME_EXTENTS */
 	time = sched_clock() << DEBUG_SHIFT;
-	preempt_enable_notrace();
+	preempt_enable_no_resched_notrace();
 
 	return time;
 }
-- 
1.6.0.4

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Impact: prevent a trace recursion
> 
> After some tests with function graph tracer under x86-32, I saw some recursions
> caused by ring_buffer_time_stamp() that calls preempt_enable_no_notrace() which
> calls preempt_schedule() which is traced itself.
> 
> This patch re-enables preemption without rescheduling.
> 
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/ring_buffer.c |    2 +-
>  1 files changed, 1 insertions(+), 1 deletions(-)

applied to tip/tracing/ftrace, thanks Frederic!

Does this explain+fix the weird crashes/reboots you were seeing?

	Ingo

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Frédéric Weisbecker]

2008/12/16 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> Impact: prevent a trace recursion
>>
>> After some tests with function graph tracer under x86-32, I saw some recursions
>> caused by ring_buffer_time_stamp() that calls preempt_enable_no_notrace() which
>> calls preempt_schedule() which is traced itself.
>>
>> This patch re-enables preemption without rescheduling.
>>
>> Cc: Steven Rostedt <rostedt@goodmis.org>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> ---
>>  kernel/trace/ring_buffer.c |    2 +-
>>  1 files changed, 1 insertions(+), 1 deletions(-)
>
> applied to tip/tracing/ftrace, thanks Frederic!
>
> Does this explain+fix the weird crashes/reboots you were seeing?
>
>        Ingo
>

No, actually the functions tracers are protected against recursion,
but rescheduling attempts
during all trace insertions (and moreover a call to
prepare_ftrace_return with cancelled insertion)
is a useless payload.

The hard reboots I've seen are related to x86-64 while
disabling/reenabling a CPU through /sys/device/system/cpu
No tracer was enabled at these times (the problem still remains with
latest updates on -tip for half an hour).

One other thing: I've seen these pointless calls to preempt_schedule
while testing the function graph tracer on
VirtualBox. Since it provides virtual serial lines, it was more easy
to debug than usual (I haven't any serial line
on my box).
The function graph tracer hangs on VirtualBox with a x86-32 -tip. It
seems that the tracing is too slow and so hrtimer_interrupt()
does an eternal loop, assuming that a new time update has to be done
(because too much time elapsed during th tracing) after each
iteration.
I'm not sure what to do...disabling tracing for hrtimers or....

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Steven Rostedt]

On Tue, 16 Dec 2008, Fr?d?ric Weisbecker wrote:
> 
> The hard reboots I've seen are related to x86-64 while
> disabling/reenabling a CPU through /sys/device/system/cpu
> No tracer was enabled at these times (the problem still remains with
> latest updates on -tip for half an hour).

Do you have STACK_TRACER enabled?

-- Steve

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Frédéric Weisbecker]

2008/12/16 Steven Rostedt <rostedt@goodmis.org>:
>
>
> On Tue, 16 Dec 2008, Fr?d?ric Weisbecker wrote:
>>
>> The hard reboots I've seen are related to x86-64 while
>> disabling/reenabling a CPU through /sys/device/system/cpu
>> No tracer was enabled at these times (the problem still remains with
>> latest updates on -tip for half an hour).
>
> Do you have STACK_TRACER enabled?
>
> -- Steve
>

Yes. Do you think the origin comes from the fact that ftrace is
running with stack tracer?

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Frédéric Weisbecker]

2008/12/16 Steven Rostedt <rostedt@goodmis.org>:
>
>
> On Tue, 16 Dec 2008, Fr?d?ric Weisbecker wrote:
>>
>> The hard reboots I've seen are related to x86-64 while
>> disabling/reenabling a CPU through /sys/device/system/cpu
>> No tracer was enabled at these times (the problem still remains with
>> latest updates on -tip for half an hour).
>
> Do you have STACK_TRACER enabled?
>
> -- Steve
>

You were right. I've just built a kernel without STACK_TRACER and the
problem disappears...

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/12/16 Steven Rostedt <rostedt@goodmis.org>:
> >
> >
> > On Tue, 16 Dec 2008, Fr?d?ric Weisbecker wrote:
> >>
> >> The hard reboots I've seen are related to x86-64 while
> >> disabling/reenabling a CPU through /sys/device/system/cpu
> >> No tracer was enabled at these times (the problem still remains with
> >> latest updates on -tip for half an hour).
> >
> > Do you have STACK_TRACER enabled?
> >
> > -- Steve
> >
> 
> You were right. I've just built a kernel without STACK_TRACER and the 
> problem disappears...

i noticed high stack-tracer overhead too. Which is understandable i guess: 
the stack tracer keeps the mcount callbacks running all the time and can 
save the stack backtrace of the highest-stack-usage point in time that the 
kernel ever has hit in the past. That is a pretty powerful debug 
capability, with appropriate costs.

	Ingo

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Steven Rostedt]

On Tue, 16 Dec 2008, Ingo Molnar wrote:
> 
> i noticed high stack-tracer overhead too. Which is understandable i guess: 
> the stack tracer keeps the mcount callbacks running all the time and can 
> save the stack backtrace of the highest-stack-usage point in time that the 
> kernel ever has hit in the past. That is a pretty powerful debug 
> capability, with appropriate costs.

I was thinking of having a way to start and stop the stack tracer. This 
way we can actually have it on by default with anything that has dynamic 
ftace. To enable it durning boot would require a kernel command line 
option. Other than that, I would have a sysctl enable it.

-- Steve

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/12/16 Ingo Molnar <mingo@elte.hu>:
> >
> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> >
> >> Impact: prevent a trace recursion
> >>
> >> After some tests with function graph tracer under x86-32, I saw some recursions
> >> caused by ring_buffer_time_stamp() that calls preempt_enable_no_notrace() which
> >> calls preempt_schedule() which is traced itself.
> >>
> >> This patch re-enables preemption without rescheduling.
> >>
> >> Cc: Steven Rostedt <rostedt@goodmis.org>
> >> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> >> ---
> >>  kernel/trace/ring_buffer.c |    2 +-
> >>  1 files changed, 1 insertions(+), 1 deletions(-)
> >
> > applied to tip/tracing/ftrace, thanks Frederic!
> >
> > Does this explain+fix the weird crashes/reboots you were seeing?
> >
> >        Ingo
> >
> 
> No, actually the functions tracers are protected against recursion,
> but rescheduling attempts
> during all trace insertions (and moreover a call to
> prepare_ftrace_return with cancelled insertion)
> is a useless payload.
> 
> The hard reboots I've seen are related to x86-64 while 
> disabling/reenabling a CPU through /sys/device/system/cpu No tracer was 
> enabled at these times (the problem still remains with latest updates on 
> -tip for half an hour).
> 
> One other thing: I've seen these pointless calls to preempt_schedule 
> while testing the function graph tracer on VirtualBox. Since it provides 
> virtual serial lines, it was more easy to debug than usual (I haven't 
> any serial line on my box). The function graph tracer hangs on 
> VirtualBox with a x86-32 -tip. It seems that the tracing is too slow and 
> so hrtimer_interrupt() does an eternal loop, assuming that a new time 
> update has to be done (because too much time elapsed during th tracing) 
> after each iteration. I'm not sure what to do...disabling tracing for 
> hrtimers or....

reduce HZ?

	Ingo

Re: [PATCH] tracing/ftrace: use preempt_enable_no_resched_notrace in ring_buffer_time_stamp()

[Frédéric Weisbecker]

2008/12/16 Ingo Molnar <mingo@elte.hu>:
>
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
>
>> 2008/12/16 Ingo Molnar <mingo@elte.hu>:
>> >
>> > * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>> >
>> >> Impact: prevent a trace recursion
>> >>
>> >> After some tests with function graph tracer under x86-32, I saw some recursions
>> >> caused by ring_buffer_time_stamp() that calls preempt_enable_no_notrace() which
>> >> calls preempt_schedule() which is traced itself.
>> >>
>> >> This patch re-enables preemption without rescheduling.
>> >>
>> >> Cc: Steven Rostedt <rostedt@goodmis.org>
>> >> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> >> ---
>> >>  kernel/trace/ring_buffer.c |    2 +-
>> >>  1 files changed, 1 insertions(+), 1 deletions(-)
>> >
>> > applied to tip/tracing/ftrace, thanks Frederic!
>> >
>> > Does this explain+fix the weird crashes/reboots you were seeing?
>> >
>> >        Ingo
>> >
>>
>> No, actually the functions tracers are protected against recursion,
>> but rescheduling attempts
>> during all trace insertions (and moreover a call to
>> prepare_ftrace_return with cancelled insertion)
>> is a useless payload.
>>
>> The hard reboots I've seen are related to x86-64 while
>> disabling/reenabling a CPU through /sys/device/system/cpu No tracer was
>> enabled at these times (the problem still remains with latest updates on
>> -tip for half an hour).
>>
>> One other thing: I've seen these pointless calls to preempt_schedule
>> while testing the function graph tracer on VirtualBox. Since it provides
>> virtual serial lines, it was more easy to debug than usual (I haven't
>> any serial line on my box). The function graph tracer hangs on
>> VirtualBox with a x86-32 -tip. It seems that the tracing is too slow and
>> so hrtimer_interrupt() does an eternal loop, assuming that a new time
>> update has to be done (because too much time elapsed during th tracing)
>> after each iteration. I'm not sure what to do...disabling tracing for
>> hrtimers or....
>
> reduce HZ?
>
>        Ingo
>

I just switched from 250 to 100 HZ. And it remains the same. But I
commented out the early_printk which could consume some
time too.
Perhaps there is one other thing that makes it hanging. I will
investigate more...
Did someone make some tests with function graph tracer on 32 bits
these last days?