What might cause a single "rcu_sched detected stall on CPU" warning in syslog?

Question

Environment: Linux [hostname] 3.2.0-4-amd64 #1 SMP Debian 3.2.96-2 x86_64 GNU/Linux Hardware: AMD Opteron(tm) Processor 6344, 6x2MiB L2, 2x8MiB L3, 6-core ht (12 logical cores)

Today I got a warning in syslog:

Feb 28 09:58:53 amalthea kernel: [4367033.060016] INFO: rcu_bh detected stall on CPU 10 (t=0 jiffies)
Feb 28 09:58:53 amalthea kernel: [4367033.060018] sending NMI to all CPUs:

Followed by a dump of CPU state. There seems to be nothing "bad" leading up to this situation in the log.

The server is still running, no (apparent) stalled processes, etc., and the warning has not repeated itself in the hour or so it's been since it happened.

I've skimmed through some information on RCU's stall detector (it's far too technical for me to really understand), and I can see that:

1. My CPU was stalled for t=0 jiffies
2. There is no "detected by" CPU

There is a note in that document that suggests to me this may be a false-positive:

["Stall ended before state dump start"] is rare, but does happen from time to time in real life. It is also possible for a zero-jiffy stall to be flagged in this case, depending on how the stall warning and the grace-period initialization happen to interact. Please note that it is not possible to entirely eliminate this sort of false positive without resorting to things like stop_machine(), which is overkill for this sort of problem.

(Emphasis mine)

I didn't get a "Stall ended before state dump start" message, but I also didn't seem to get much else in terms of diagnostics other than the slew of CPU-dumps that came after the two log lines shown above.

I can post more information from the CPU-dump if it would be helpful. Nothing jumped-out at me, though I'm no expert.

What could have caused this situation? Is it likely to be a false-positive based solely upon the t=0 jiffies data point, plus no other diagnostic information printed to the log?

(Please note that this question is distinct from rcu_sched detected stall on CPU, which seems to have indicated a "real problem".)

Answer 1

Most likely, this is caused by one of three things:

1. A very hard to trigger kernel bug. I don't think this is likely though, as the RCU stuff is so core to the kernel that any bugs there are likely to be hit by just about everyone.
2. Bad RAM. Memory corruption caused by a bad memory module can quite easily cause bizarre stuff like this to happen.
3. A transient memory error caused by something other than the memory itself. Similar to the above, but not likely to show up again. This is the type of thing that ECC memory tries to protect against (but can't completely because it's fully possible for something to go wrong in the ECC logic).

Unless it' happens again, you can probably assume it's case 3 and just move on. If it does happen again, look for similarities in the surrounding kernel messages and/or check your RAM.

Answer 2

I hit this kind of error (CPU stall) on an NVidia Jetson board.

After talking with NVidia and working on our Jetsons', I've found out that some of our cards would receive something like 80,000 interrupts per seconds just by the bluetooth device. Disabling that device corresponding module prevented the CPU stalls.

To know how many interrupts you get, you look at the /proc/interrupts. Note that my stalls would occur because the RJ45 was used too and with so many interrupts I would hit a Linux kernel deadlock (note that it's probably not the kernel itself, but the drivers handling the bluetooth and RJ45).

Here is an example where we see several of the functions reference "net" or "ip". We also see the el1_irq which tells us we're handling an IRQ.

So as per Austin's list, I hit a problem as defined in (1).

Feb  1 08:53:16 ve5 kernel: [ 1459.074481] INFO: rcu_preempt self-detected stall on CPU
Feb  1 08:53:16 ve5 kernel: [ 1459.074646]      0-...: (8 GPs behind) idle=ea9/140000000000001/0 softirq=32059/32059 fqs=2112 
Feb  1 08:53:16 ve5 kernel: [ 1459.074794]       (t=5250 jiffies g=10249 c=10248 q=48)
Feb  1 08:53:16 ve5 kernel: [ 1459.074906] Task dump for CPU 0:
Feb  1 08:53:16 ve5 kernel: [ 1459.074926] ksoftirqd/0     R  running task        0     3      2 0x00000002
Feb  1 08:53:16 ve5 kernel: [ 1459.074943] Call trace:
Feb  1 08:53:16 ve5 kernel: [ 1459.074963] [<ffffff800808bdb8>] dump_backtrace+0x0/0x198
Feb  1 08:53:16 ve5 kernel: [ 1459.074972] [<ffffff800808c37c>] show_stack+0x24/0x30
Feb  1 08:53:16 ve5 kernel: [ 1459.074983] [<ffffff80080ecf70>] sched_show_task+0xf8/0x148
Feb  1 08:53:16 ve5 kernel: [ 1459.074991] [<ffffff80080efc70>] dump_cpu_task+0x48/0x58
Feb  1 08:53:16 ve5 kernel: [ 1459.075001] [<ffffff80081c1acc>] rcu_dump_cpu_stacks+0xb8/0xec
Feb  1 08:53:16 ve5 kernel: [ 1459.075012] [<ffffff8008132450>] rcu_check_callbacks+0x728/0xa48
Feb  1 08:53:16 ve5 kernel: [ 1459.075020] [<ffffff8008138cac>] update_process_times+0x34/0x60
Feb  1 08:53:16 ve5 kernel: [ 1459.075030] [<ffffff800814a218>] tick_sched_handle.isra.5+0x38/0x70
Feb  1 08:53:16 ve5 kernel: [ 1459.075037] [<ffffff800814a29c>] tick_sched_timer+0x4c/0x90
Feb  1 08:53:16 ve5 kernel: [ 1459.075044] [<ffffff80081399e0>] __hrtimer_run_queues+0xd8/0x360
Feb  1 08:53:16 ve5 kernel: [ 1459.075051] [<ffffff800813a330>] hrtimer_interrupt+0xa8/0x1e0
Feb  1 08:53:16 ve5 kernel: [ 1459.075061] [<ffffff8008bffe98>] arch_timer_handler_phys+0x38/0x58
Feb  1 08:53:16 ve5 kernel: [ 1459.075071] [<ffffff8008126f10>] handle_percpu_devid_irq+0x90/0x2b0
Feb  1 08:53:16 ve5 kernel: [ 1459.075078] [<ffffff80081214f4>] generic_handle_irq+0x34/0x50
Feb  1 08:53:16 ve5 kernel: [ 1459.075085] [<ffffff8008121bd8>] __handle_domain_irq+0x68/0xc0
Feb  1 08:53:16 ve5 kernel: [ 1459.075092] [<ffffff8008080d44>] gic_handle_irq+0x5c/0xb0
Feb  1 08:53:16 ve5 kernel: [ 1459.075099] [<ffffff8008082c28>] el1_irq+0xe8/0x194
Feb  1 08:53:16 ve5 kernel: [ 1459.075108] [<ffffff8008231de4>] kmem_cache_alloc+0x114/0x2c0
Feb  1 08:53:16 ve5 kernel: [ 1459.075118] [<ffffff8008db94a4>] dst_alloc+0x6c/0xb0
Feb  1 08:53:16 ve5 kernel: [ 1459.075127] [<ffffff8008df6a2c>] rt_dst_alloc+0x74/0xe8
Feb  1 08:53:16 ve5 kernel: [ 1459.075134] [<ffffff8008df7ca0>] ip_route_input_noref+0x3c0/0x8f8
Feb  1 08:53:16 ve5 kernel: [ 1459.075144] [<ffffff8008e34a00>] arp_process+0x3e8/0x708
Feb  1 08:53:16 ve5 kernel: [ 1459.075152] [<ffffff8008e34e70>] arp_rcv+0x118/0x1a8
Feb  1 08:53:16 ve5 kernel: [ 1459.075161] [<ffffff8008da9c20>] __netif_receive_skb_core+0x3b8/0xad8
Feb  1 08:53:16 ve5 kernel: [ 1459.075169] [<ffffff8008dad010>] __netif_receive_skb+0x28/0x78
Feb  1 08:53:16 ve5 kernel: [ 1459.075175] [<ffffff8008dad08c>] netif_receive_skb_internal+0x2c/0xb0
Feb  1 08:53:16 ve5 kernel: [ 1459.075182] [<ffffff8008dadcb4>] napi_gro_receive+0x15c/0x188
Feb  1 08:53:16 ve5 kernel: [ 1459.075192] [<ffffff800894dd90>] eqos_napi_poll_rx+0x358/0x430
Feb  1 08:53:16 ve5 kernel: [ 1459.075199] [<ffffff8008daf2e4>] net_rx_action+0xf4/0x358
Feb  1 08:53:16 ve5 kernel: [ 1459.075206] [<ffffff8008081054>] __do_softirq+0x13c/0x3b0
Feb  1 08:53:16 ve5 kernel: [ 1459.075215] [<ffffff80080baf38>] run_ksoftirqd+0x48/0x58
Feb  1 08:53:16 ve5 kernel: [ 1459.075225] [<ffffff80080e07c8>] smpboot_thread_fn+0x160/0x248
Feb  1 08:53:16 ve5 kernel: [ 1459.075232] [<ffffff80080dbe64>] kthread+0xec/0xf0
Feb  1 08:53:16 ve5 kernel: [ 1459.075239] [<ffffff80080838a0>] ret_from_fork+0x10/0x30