timer: lockup in run_timer_softirq()

Hi all,

While fuzzing with trinity inside a KVM tools guest running latest -next, I've stumbled on the following spew:

[ 2536.440007] BUG: soft lockup - CPU#0 stuck for 23s! [trinity-child86:12368]
[ 2536.440007] Call Trace:
[ 2536.440007]  <IRQ>
[ 2536.440007]  [<ffffffff8113d180>] run_timer_softirq+0x2d0/0x330
[ 2536.440007]  [<ffffffff8113b400>] ? lock_timer_base+0x70/0x70
[ 2536.440007]  [<ffffffff81132b21>] __do_softirq+0x261/0x4d0
[ 2536.440007]  [<ffffffff81132ed6>] irq_exit+0x86/0x120
[ 2536.440007]  [<ffffffff841a43ea>] smp_apic_timer_interrupt+0x4a/0x60
[ 2536.440007]  [<ffffffff841a2d32>] apic_timer_interrupt+0x72/0x80
[ 2536.440007]  <EOI>
[ 2536.440007]  [<ffffffff84198ef7>] ? retint_restore_args+0x13/0x13
[ 2536.440007]  [<ffffffff812355e5>] ? user_enter+0x135/0x150
[ 2536.440007]  [<ffffffff81077d6d>] syscall_trace_leave+0x12d/0x160
[ 2536.440007]  [<ffffffff841a2337>] int_check_syscall_exit_work+0x34/0x3d
[ 2536.440007] Code: 01 fd 48 89 df e8 45 5b 8f fd e8 b0 f1 00 fd 48 83 3d 30 e6 8a 01 00 75 0e 0f 

0b 0f 1f 40 00 eb fe 66 0f 1f 44 00 00 fb 66 66 90 <66> 66 90 bf 01 00 00 00 e8 17 4f 00 00 65 48 8b 04 25 88 d9 00

While going through the NMI dump, I noticed that it's very incomplete, and full of:

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 

697182.008 msecs

Quoted 20 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running latest -next, I've stumbled on the following spew:

[ 2536.440007] BUG: soft lockup - CPU#0 stuck for 23s! [trinity-child86:12368]
[ 2536.440007] Call Trace:
[ 2536.440007]  <IRQ>
[ 2536.440007]  [<ffffffff8113d180>] run_timer_softirq+0x2d0/0x330
[ 2536.440007]  [<ffffffff8113b400>] ? lock_timer_base+0x70/0x70
[ 2536.440007]  [<ffffffff81132b21>] __do_softirq+0x261/0x4d0
[ 2536.440007]  [<ffffffff81132ed6>] irq_exit+0x86/0x120
[ 2536.440007]  [<ffffffff841a43ea>] smp_apic_timer_interrupt+0x4a/0x60
[ 2536.440007]  [<ffffffff841a2d32>] apic_timer_interrupt+0x72/0x80
[ 2536.440007]  <EOI>
[ 2536.440007]  [<ffffffff84198ef7>] ? retint_restore_args+0x13/0x13
[ 2536.440007]  [<ffffffff812355e5>] ? user_enter+0x135/0x150
[ 2536.440007]  [<ffffffff81077d6d>] syscall_trace_leave+0x12d/0x160
[ 2536.440007]  [<ffffffff841a2337>] int_check_syscall_exit_work+0x34/0x3d
[ 2536.440007] Code: 01 fd 48 89 df e8 45 5b 8f fd e8 b0 f1 00 fd 48 83 3d 30 e6 8a 01 00 75 0e 0f

Quoted 7 lines

0b 0f 1f 40 00 eb fe 66 0f 1f 44 00 00 fb 66 66 90 <66> 66 90 bf 01 00 00 00 e8 17 4f 00 00 65 48 8b 04 25 88 d9 00

While going through the NMI dump, I noticed that it's very incomplete, and full of:

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run:

697182.008 msecs

I've been reporting these (and other traces) for a while https://lkml.org/lkml/2013/7/5/185 [1] on bare-metal.

I've not managed to find time yet to try and narrow down the exact combination of trinity syscalls that causes this. Sometimes it happens quickly, sometimes after a few hours (even when run with the same seeds, it seems variable)

Quoted 3 lines · Dave Jones

Quoted 2 lines

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run:

697182.008 msecs

Quoted 2 lines

I've been reporting these (and other traces) for a while https://lkml.org/lkml/2013/7/5/185 [1] on bare-metal.

Interesting. It's the first time I'm seeing these, but I haven't really changed anything in my configuration.

Are you also seeing the "NMI handler took too long" messages?

Quoted 8 lines · Sasha Levin

Quoted 5 lines · Dave Jones

Quoted 2 lines

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run:

697182.008 msecs

I've been reporting these (and other traces) for a while https://lkml.org/lkml/2013/7/5/185 [1] on bare-metal.

Quoted 4 lines

Interesting. It's the first time I'm seeing these, but I haven't really changed anything in my configuration.

Are you also seeing the "NMI handler took too long" messages?

Now that I look closer, one difference is you're seeing arch_trigger_all_cpu_backtrace_handler in that message. I'm seeing them from perf_event_nmi_handler.

perf huh? I also have this spew I'm currently working on, it seems related:

[ 1443.380407] ------------[ cut here ]------------
[ 1443.381713] WARNING: CPU: 20 PID: 49263 at kernel/lockdep.c:3552 check_flags+0x16b/0x220()
[ 1443.383988] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[ 1443.385452] Modules linked in:
[ 1443.386459] CPU: 20 PID: 49263 Comm: trinity-child50 Tainted: G        W
3.10.0-next-20130709-sasha #3953
[ 1443.388735]  0000000000000de0 ffff880805e03ab8 ffffffff84191329 ffffffff8519f386
[ 1443.390082]  ffff880805e03b08 ffff880805e03af8 ffffffff811279cc ffffffff8519f386
[ 1443.390082]  0000000000000000 ffff8807cf898000 ffffffff85a66940 0000000000000082
[ 1443.390082] Call Trace:
[ 1443.390082]  <IRQ>  [<ffffffff84191329>] dump_stack+0x52/0x87
[ 1443.390082]  [<ffffffff811279cc>] warn_slowpath_common+0x8c/0xc0
[ 1443.390082]  [<ffffffff81127ab6>] warn_slowpath_fmt+0x46/0x50
[ 1443.390082]  [<ffffffff8419d649>] ? sub_preempt_count+0x9/0xf0
[ 1443.390082]  [<ffffffff811a192b>] check_flags+0x16b/0x220
[ 1443.390082]  [<ffffffff811a2ee7>] lock_is_held+0x77/0x110
[ 1443.390082]  [<ffffffff8419d644>] ? sub_preempt_count+0x4/0xf0
[ 1443.390082]  [<ffffffff8122dafe>] perf_tp_event+0xbe/0x450
[ 1443.390082]  [<ffffffff8122de62>] ? perf_tp_event+0x422/0x450
[ 1443.390082]  [<ffffffff8419d644>] ? sub_preempt_count+0x4/0xf0
[ 1443.390082]  [<ffffffff812185f2>] perf_ftrace_function_call+0xc2/0xe0
[ 1443.390082]  [<ffffffff811f8c78>] ? ftrace_ops_control_func+0xc8/0x140
[ 1443.427495]  [<ffffffff8419d644>] ? sub_preempt_count+0x4/0xf0
[ 1443.427495]  [<ffffffff81131917>] ? __local_bh_enable+0xc7/0xd0
[ 1443.427495]  [<ffffffff811f8c78>] ftrace_ops_control_func+0xc8/0x140
[ 1443.427495]  [<ffffffff841a1c3c>] ftrace_call+0x5/0x2f
[ 1443.427495]  [<ffffffff841a1c3c>] ? ftrace_call+0x5/0x2f
[ 1443.427495]  [<ffffffff81175b87>] ? vtime_account_irq_exit+0x67/0x80
[ 1443.427495]  [<ffffffff8419d649>] ? sub_preempt_count+0x9/0xf0
[ 1443.427495]  [<ffffffff8419d649>] ? sub_preempt_count+0x9/0xf0
[ 1443.427495]  [<ffffffff8113185e>] ? __local_bh_enable+0xe/0xd0
[ 1443.427495]  [<ffffffff8419d649>] ? sub_preempt_count+0x9/0xf0
[ 1443.427495]  [<ffffffff81131917>] __local_bh_enable+0xc7/0xd0
[ 1443.427495]  [<ffffffff81132d07>] __do_softirq+0x447/0x4d0
[ 1443.427495]  [<ffffffff8419d649>] ? sub_preempt_count+0x9/0xf0
[ 1443.427495]  [<ffffffff81132ed6>] irq_exit+0x86/0x120
[ 1443.427495]  [<ffffffff841a43ea>] smp_apic_timer_interrupt+0x4a/0x60
[ 1443.427495]  [<ffffffff841a2d32>] apic_timer_interrupt+0x72/0x80

[ 1443.427495]  <EOI>  [<ffffffff81130542>] ? do_setitimer+0x242/0x2a0
[ 1443.427495]  [<ffffffff8419871c>] ? _raw_spin_unlock_irq+0x4c/0x80
[ 1443.427495]  [<ffffffff84198700>] ? _raw_spin_unlock_irq+0x30/0x80
[ 1443.427495]  [<ffffffff81130542>] do_setitimer+0x242/0x2a0
[ 1443.427495]  [<ffffffff811306fa>] alarm_setitimer+0x3a/0x70
[ 1443.427495]  [<ffffffff8113b41e>] SyS_alarm+0xe/0x20
[ 1443.427495]  [<ffffffff841a2240>] tracesys+0xdd/0xe2
[ 1443.427495] ---[ end trace e3b9a6b9c7462a51 ]---

Fun.. :-) we trace __local_bh_enable() and hit a ftrace callback between telling lockdep we enabled softirqs and actually doing so.

I'm just a tad confused by the trace; it says we go:
lock_is_held()
check_flags()

Looking at perf_tp_event() this would most likely be from:

  ctx = rcu_dereference(task->perf_event_ctxp[perf_sw_context]);

Where the lock_is_held() would be from rcu_dereference_check()'s rcu_read_lock_sched_held(). However, by there we've already passed rcu_read_lock() which includes rcu_lock_acquire() -> lock_acquire() -> check_flags(). So it should've triggered there.

Ideally we'd not trace __local_bh_enable() at all, seeing as how any RCU usage in there would be bound to trigger this.

Quoted 7 lines · Peter Zijlstra

Fun.. :-) we trace __local_bh_enable() and hit a ftrace callback between telling lockdep we enabled softirqs and actually doing so.

I'm just a tad confused by the trace; it says we go:
lock_is_held()
check_flags()

Quoted 3 lines

Looking at perf_tp_event() this would most likely be from:

  ctx = rcu_dereference(task->perf_event_ctxp[perf_sw_context]);

Function tracing should not be treated as a normal trace point. It is much more invasive, and there's things that one should be weary about when using it.

Quoted 8 lines

Where the lock_is_held() would be from rcu_dereference_check()'s rcu_read_lock_sched_held(). However, by there we've already passed rcu_read_lock() which includes rcu_lock_acquire() -> lock_acquire() -> check_flags(). So it should've triggered there.

Ideally we'd not trace __local_bh_enable() at all, seeing as how any RCU usage in there would be bound to trigger this.

I find it very useful to trace __local_bh_enable(). I also trace RCU calls.

When using function tracing, you need to use
rcu_dereference_raw_notrace().

Also, function tracing callbacks should avoid rcu_read_lock(), as that's traced as well. You can use preempt_disable_notrace() for rcu usage.

but but but preempt_disable_notrace() isn't an rcu_read_lock().. You can only do that for rcu_sched.

Anyway, I don't see a nice way out of this mess :/ the entire perf core uses regular RCU and converting all that is going to me a nasty big patch.

Quoted 2 lines · Peter Zijlstra

but but but preempt_disable_notrace() isn't an rcu_read_lock().. You can only do that for rcu_sched.

Right. And not even rcu_sched is safe, as function tracing can trace functions out of rcu scope. That's why I had to add that code to do a schedule_on_each_cpu() in ftrace.

Quoted 3 lines

Anyway, I don't see a nice way out of this mess :/ the entire perf core uses regular RCU and converting all that is going to me a nasty big patch.

There is an easier way. We can add a way to have perf not trace specific functions. Now there's already infrastructure there to pick and choose what to trace and what not to for individual function tracing users like perf. The trick will be how to annotate them.

If there's a way to mark a function without moving it to a section, this would be possible. Perhaps similar to EXPORT_SYMBOL(). We could add a PERF_NOTRACE().

static void __local_bh_enable()

{
	[...]
}

PERF_NOTRACE(__local_bh_enable);

And add these to a black list of functions that perf should not trace.

How's that sound?

I'm afraid this is going to be hard to create and hard to keep correct :/

Other than that, a function tracer environment that is safer to use might be useful for other people as well.

Quoted 3 lines

Other than that, a function tracer environment that is safer to use might be useful for other people as well.

Not sure how to make the environment safe, as the main purpose of the function trace is to debug those hard to debug locations, like NMIs, RCU, dynamic ticks, etc. To ensure a "safe" environment, it would cripple the tracer.

Hmm, what would you state as a safe environment? How can we detect if the environment is safe to trace or not?

Quoted 11 lines · Steven Rostedt

Quoted 3 lines

Other than that, a function tracer environment that is safer to use might be useful for other people as well.

Not sure how to make the environment safe, as the main purpose of the function trace is to debug those hard to debug locations, like NMIs, RCU, dynamic ticks, etc. To ensure a "safe" environment, it would cripple the tracer.

Hmm, what would you state as a safe environment? How can we detect if the environment is safe to trace or not?

Maybe I misunderstood you. You mean to have this environment be something for not just perf, and have the macro be:

NONSAFE_TRACE(__local_bh_enable);

?

Then, any ftrace user could set a flag in the registering of its ops to 'safe_only_functions'. And it will ignore all of these locations. There's really not many of them, so it may not be too hard to weed out.

Quoted 21 lines · Steven Rostedt

Quoted 11 lines · Steven Rostedt

Quoted 3 lines

Other than that, a function tracer environment that is safer to use might be useful for other people as well.

Not sure how to make the environment safe, as the main purpose of the function trace is to debug those hard to debug locations, like NMIs, RCU, dynamic ticks, etc. To ensure a "safe" environment, it would cripple the tracer.

Hmm, what would you state as a safe environment? How can we detect if the environment is safe to trace or not?

Maybe I misunderstood you. You mean to have this environment be something for not just perf, and have the macro be:

NONSAFE_TRACE(__local_bh_enable);

?

Quoted 3 lines

Then, any ftrace user could set a flag in the registering of its ops to 'safe_only_functions'. And it will ignore all of these locations. There's really not many of them, so it may not be too hard to weed out.

Yah, like that. But that doesn't invalidate your question as to what 'safe' would encompass. I think RCU/lockdep would be the big thing for perf, not sure it should be wider than that.

While going through the NMI dump, I noticed that it's very incomplete, and full of:

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler)

took too long to run: 697182.008 msecs

Quoted 4 lines · Sasha Levin

While going through the NMI dump, I noticed that it's very incomplete, and full of:

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler)

took too long to run: 697182.008 msecs

Now I would actually expect arch_trigger_all_cpu_backtrace_handler() to issue this warning, that said, ~700 seconds is a bit long, I'm fairly sure it didn't actually take that long, you'd have noticed your vm being 'away' for 10+ minutes I'd think, no?

There's something entirely fishy with that stuff, let me to stare at it.

Quoted 12 lines · Peter Zijlstra

Quoted 4 lines · Sasha Levin

While going through the NMI dump, I noticed that it's very incomplete, and full of:

[ 2536.500130] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler)

took too long to run: 697182.008 msecs

Now I would actually expect arch_trigger_all_cpu_backtrace_handler() to issue this warning, that said, ~700 seconds is a bit long, I'm fairly sure it didn't actually take that long, you'd have noticed your vm being 'away' for 10+ minutes I'd think, no?

Quoted 1 line

There's something entirely fishy with that stuff, let me to stare at it.

Yeah, it didn't actually hang that long - that number is bogus.