tracing/function-graph-tracer: prevent from hrtimer interrupt infinite loop

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

Quoted 11 lines · Frederic Weisbecker

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

hm, i dont really like this solution - it just works around the problem by 'speeding up' the system. If we have a _real_ slow system, there's no such way for us to speed it up.

Thomas, what do you think - would you expect this lockup to happen on really slow systems? If yes, is there a way we could avoid it from happening - by driving some sort of 'mandatory interval', that is doubled in size every time we detect such a bad hrtimer loop?

Quoted 6 lines

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

Quoted 6 lines

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

hm, i dont really like this solution - it just works around the problem by 'speeding up' the system. If we have a _real_ slow system, there's no such way for us to speed it up.

Thomas, what do you think - would you expect this lockup to happen on really slow systems? If yes, is there a way we could avoid it from happening - by driving some sort of 'mandatory interval', that is doubled in size every time we detect such a bad hrtimer loop?

Ingo

Quoted 14 lines · Frederic Weisbecker

Quoted 6 lines

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

Quoted 6 lines

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

Quoted 8 lines

hm, i dont really like this solution - it just works around the problem by 'speeding up' the system. If we have a _real_ slow system, there's no such way for us to speed it up.

Thomas, what do you think - would you expect this lockup to happen on really slow systems? If yes, is there a way we could avoid it from happening - by driving some sort of 'mandatory interval', that is doubled in size every time we detect such a bad hrtimer loop?

In reality I have not seen such a problem yet, even on an old real slow P1 which I tricked to do highres, but of course if we add such time consuming debugs and make it slow enough the system will spend all the time running the tick timer :)

We should at least warn once about such a loop.

I'm not sure about the mandatory interval though:

Try the same test with HZ=1000 periodic mode (HIGHRES/NOHZ=off) and I bet you see the same problem, just not in hrtimer_interrupt().

Thanks,

tglx

2008/12/18 Ingo Molnar <[email protected]>:

Quoted 15 lines · Frederic Weisbecker

Quoted 12 lines

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

Quoted 3 lines

hm, i dont really like this solution - it just works around the problem by 'speeding up' the system. If we have a _real_ slow system, there's no such way for us to speed it up.

It doesn' speed up the system actually. That's not the goal of this patch.

Quoted 14 lines · Ingo Molnar

Quoted 11 lines · Frederic Weisbecker

Impact: fix a system hang on slow systems

While testing the function graph tracer on VirtualBox, I had a system hang immediatly after enabling the tracer.

If hrtimer is enabled on kernel, a slow system can spend too much time during tracing the hrtimer_interrupt which will do eternal loops, assuming it always have to retry its process because too much time elapsed during its time update. Now we provide a feature which lurks at the number of retries on hrtimer_interrupt. After 10 retries, the function graph tracer will definetly stop its tracing.

Quoted 8 lines

hm, i dont really like this solution - it just works around the problem by 'speeding up' the system. If we have a _real_ slow system, there's no such way for us to speed it up.

Thomas, what do you think - would you expect this lockup to happen on really slow systems? If yes, is there a way we could avoid it from happening - by driving some sort of 'mandatory interval', that is doubled in size every time we detect such a bad hrtimer loop?

In reality I have not seen such a problem yet, even on an old real slow P1 which I tricked to do highres, but of course if we add such time consuming debugs and make it slow enough the system will spend all the time running the tick timer :)

We should at least warn once about such a loop.

I'm not sure about the mandatory interval though:

Try the same test with HZ=1000 periodic mode (HIGHRES/NOHZ=off) and I bet you see the same problem, just not in hrtimer_interrupt().

i meant that abstractly. The "solution" here is that your patch turns off the function-graph-tracer. The practical effect of that is: the system gets much faster at processing hrtimer IRQs and effectively "speeds up".

ok?

Ingo

that would be important to double-check. Frederic, does the system lock up with a periodic 1khz HZ tick just as much? I.e. does the processing of a single timer interrupt take more than 1 milliseconds?

Granted, if the system is too slow to process the system clock, it's not useful.

But that's my point: instead of just randomly disabling functionality until the system gets 'fast enough' to process timer IRQs, how about dynamically and adaptively extending the required minimal timeout between hr-timer IRQs?

That will in essence self-tune the system into some minimally working state - instead of locking it up. Note that such a method would work with any source of timer IRQ slowness - not just tracing.

( And maybe the lockup is somehow hrtimer IRQ induced. If a 1khz clock
still works for Frederic then that angle has to be investigated. )

Ingo

Hmm. No, I just tested by setting 1000 HZ and disabled NOHZ, the system doesn't lockup unless I turn on the function graph tracer.

Quoted 3 lines

Hmm. No, I just tested by setting 1000 HZ and disabled NOHZ, the system doesn't lockup unless I turn on the function graph tracer.

but that's what we are interested in: the system locks up with HZ=1000 and with the tracer on - right?

Which means that it's not some hrtimer problem, but simply the traced timer tick takes more than 1 millisecond to execute under this virtualization.

Ingo

Quoted 6 lines

Which means that it's not some hrtimer problem, but simply the traced timer tick takes more than 1 millisecond to execute under this virtualization.

Ingo

Oh ok I see. Sorry I'm a bit slow today... So the solution would be to adapt dynamically the timeout between hrtimer irq. But I don't know that much hrtimer to implement such a feature...

Quoted 11 lines

Quoted 7 lines

Which means that it's not some hrtimer problem, but simply the traced timer tick takes more than 1 millisecond to execute under this virtualization.

Ingo

Oh ok I see. Sorry I'm a bit slow today... So the solution would be to adapt dynamically the timeout between hrtimer irq. But I don't know that much hrtimer to implement such a feature...

just if you want this lockup to go away. I think you did the hardest bit
already: to detect the situation reliably, without false positives. Now the 'action' needs to change: instead of 'turning off ftrace' (which is brutal - ftrace was just the last drop of water that pushed the system over the edge), we can instead do 'double the minimum clockevent delta threshold'.

there's already such code in kernel/time/tick-oneshot.c:

               /*
                * We tried 2 times to program the device with the given
                * min_delta_ns. If that's not working then we double it
                * and emit a warning.
                */
               if (++i > 2) {
                       /* Increase the min. delta and try again */
                       if (!dev->min_delta_ns)
                               dev->min_delta_ns = 5000;
                       else
                               dev->min_delta_ns += dev->min_delta_ns >> 1;

what would be needed is to simply double ->min_delta_ns on every such situation you detect? Once you do that, it takes effect on the next tick automatically.

Or something like that. In theory. :-)

Ingo

btw., a graph-tracer buglet i noticed:

btw., a graph-tracer buglet i noticed:

 3)               |  perf_counter_task_tick() {
 3)               |    perf_counter_task_sched_out() {
 3)               |      /* c:ffff88049b184000, u:0: 0000000020ca1ab0 + 0000000000000000 = 0000000020ca1ab0
 */
 3)               |      /* sched-out counter ffff88049b184000, state: 0
 */
 3)   5.024 us    |    }
 3)               |    perf_counter_task_sched_in() {
 3)               |      /* c:ffff88049b184000, u:0: 0000000020ca1ab0 + 0000000000000000 = 0000000020ca1ab0
 */
 3)               |      /* sched-in counter ffff88049b184000, state: 1
 */
 3)   2.605 us    |    }
 3)   9.714 us    |  }
 3)               |  perf_counter_task_tick() {

the bug is that the '*/' comment closing text is printed in the next line
- that's not a linewrap, it happened like this in the trace.

The reason is that the ftrace_printk did:

       ftrace_printk("c:%p, u:%d: %016Lx + %016Lx = %016Lx\n",

the closing \n is pretty natural - especially for kernel hackers who might just turn printk()s into ftrace_printk(), to embedd printouts in function traces. So it would be nice if ftrace skipped over \n's when printing them out as embedded C comments.

Ingo

Quoted 2 lines

btw., a graph-tracer buglet i noticed:

another thing. I turned off all the options that come ahead of the 'meat' of the trace data:

# cat /debug/tracing/trace_options
print-parent nosym-offset nosym-addr noverbose noraw nohex nobin noblock
nostacktrace nosched-tree ftrace_printk noftrace_preempt nobranch annotate
nouserstacktrace nosym-userobj printk-msg-only nofuncgraph-overrun
nofuncgraph-cpu nofuncgraph-overhead nofuncgraph-proc

but i still got the 'duration' field printed:

# tracer: function_graph
#
# DURATION FUNCTION CALLS
# | | | | |

0.865 us | }

           |    alloc_page_vma() {
0.295 us    |      get_vma_policy();
0.268 us    |      policy_zonelist();
           |      __alloc_pages_internal() {
0.257 us    |        __might_sleep();
           |        get_page_from_freelist() {

i'd have expected to only see the flow of execution as it happens.

Ingo

2008/12/21 Ingo Molnar <[email protected]>:

Quoted 30 lines · Ingo Molnar

Quoted 2 lines

btw., a graph-tracer buglet i noticed:

another thing. I turned off all the options that come ahead of the 'meat' of the trace data:

# cat /debug/tracing/trace_options
print-parent nosym-offset nosym-addr noverbose noraw nohex nobin noblock
nostacktrace nosched-tree ftrace_printk noftrace_preempt nobranch annotate
nouserstacktrace nosym-userobj printk-msg-only nofuncgraph-overrun
nofuncgraph-cpu nofuncgraph-overhead nofuncgraph-proc

but i still got the 'duration' field printed:

# tracer: function_graph
#
# DURATION FUNCTION CALLS
# | | | | |

0.865 us | }

           |    alloc_page_vma() {
0.295 us    |      get_vma_policy();
0.268 us    |      policy_zonelist();
           |      __alloc_pages_internal() {
0.257 us    |        __might_sleep();
           |        get_page_from_freelist() {

Quoted 4 lines

i'd have expected to only see the flow of execution as it happens.

Ingo

Strange. I will test that.