Re: WARNING: at kernel/rcutree.c:1558 rcu_do_batch+0x386/0x3a0(),during CPU hotplug

[Fengguang Wu]

On Fri, Sep 14, 2012 at 05:48:20PM +0530, Srivatsa S. Bhat wrote:
> On 09/14/2012 05:17 PM, Fengguang Wu wrote:
> > On Thu, Sep 13, 2012 at 02:05:17PM +0530, Srivatsa S. Bhat wrote:
> >> On 09/12/2012 06:06 PM, Srivatsa S. Bhat wrote:
> >>> On 07/19/2012 10:45 PM, Paul E. McKenney wrote:
> >>>> On Thu, Jul 19, 2012 at 05:39:30PM +0530, Srivatsa S. Bhat wrote:
> >>>>> Hi Paul,
> >>>>>
> >>>>> While running a CPU hotplug stress test on v3.5-rc7+
> >>>>> (mainline commit 8a7298b7805ab) I hit this warning.
> >>>>> I haven't tried to debug this yet...
> >>>>>
> >>>>> Line number 1550 maps to:
> >>>>>
> >>>>> WARN_ON_ONCE(cpu_is_offline(smp_processor_id()));
> >>>>>
> >>>>> inside rcu_do_batch().
> >>>>
> >>>> Hello, Srivatsa,
> >>>>
> >>>> I believe that you need commit a16b7a69 (Prevent __call_rcu() from
> >>>> invoking RCU core on offline CPUs), which is currently in -tip, queued
> >>>> for 3.6.  Please see below for the patch.
> >>>>
> >>>> Does this help?
> >>>>
> >>>
> >>> Hi Paul,
> >>>
> >>> I am hitting the cpu_is_offline() warning in rcu_do_batch() (see 2 of the
> >>> examples below) occasionally while testing CPU hotplug on Thomas' smp/hotplug
> >>> branch in -tip. It does contain the commit that you had mentioned above.
> >>>
> >>
> >> I also hit some writeback related problems during some of these runs. But I was
> >> not able to reproduce them after that occurrence. (Adding relevant people to CC.)
> >>
> >> I hit the divide error shown below during the CPU hotplug test run, and the general
> > 
> > I've hit the divide error before. And I'm not luckier than you in
> > reproducing the bug. I tempt to add a test as the workaround:
> > 
> 
> Hi Fengguang,
> First of all, thanks for taking a look!
> 
> I just hit it today during my testing again! See below for the stack-traces..
> 
> > +       if (WARN_ON(!denominator))
> > +               return dirty;
> 
> Yep, I am going to try this out next and see if the denominator really became 0.

OK, thanks for the testing!

> I went through the code and I didn't find anything wrong with it. It looks pretty
> good (the denominator sanity checking part). Hmm...

Yeah, looks so..

> > btw, any chance you may share the CPU hotplug test scripts?
> > It'd be a valuable addition to my 0day boot test system.
> > 
> 
> Sure, I was using a very simple script that does offline/online in sequence. That's all.
> Please find it below. Note that adding a breather between the hotplug operations (like
> adding sleep as shown below) has the potential to expose different bugs than the normal
> stress test (no sleeps between subsequent operations). So both cases are useful to test.
> For example, with the sleep, I hit this divide error with higher probability, whereas
> without the sleep (stress test) I hit the rcu_do_batch warning more often.
> 
> (And on a slightly different note, when x86 supports CPU 0 hotplug (today it doesn't),
> you can use i = 0 instead of i = 1 in the loop. I believe that code is already in -tip).

Thank you very much for the script and the detailed notes!!

Thanks,
Fengguang

> 
> CPU hotplug test script
> -----------------------
> #! /bin/bash
> 
> NUMBER_OF_CPUS=`ls -d /sys/devices/system/cpu/cpu[0-9]* | wc -l`
> 
> cd /sys/devices/system/cpu
> 
> while [ 1 ]
> do
>         for ((i=1; i < NUMBER_OF_CPUS; i++))
>         do
>                 sleep 1;
>                 state=`cat cpu$i/online`
>                 if [ $state -eq 0 ]
>                 then
>                         echo 1 > cpu$i/online
>                 else
>                         echo 0 > cpu$i/online
>                 fi
>         done
> done
> 
> 
> >> protection fault subsequently, while trying to shutdown the machine after the test.
> > 
> 
> Dumps from the divide error and general protection fault in today's testing:
> 
> 
> [ 4831.353623] SMP alternatives: lockdep: fixing up alternatives
> [ 4831.359465] smpboot: Booting Node 1 Processor 13 APIC 0x13
> [ 4833.028342] SMP alternatives: lockdep: fixing up alternatives
> [ 4833.034188] smpboot: Booting Node 1 Processor 14 APIC 0x15
> [ 4835.693836] SMP alternatives: lockdep: fixing up alternatives
> [ 4835.699609] smpboot: Booting Node 1 Processor 15 APIC 0x17
> [ 4843.142309] Broke affinity for irq 77
> [ 4843.147605] smpboot: CPU 1 is now offline
> [ 4843.155885] CPU 9 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4844.379459] Broke affinity for irq 80
> [ 4844.384569] smpboot: CPU 2 is now offline
> [ 4844.392111] CPU 10 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4845.810713] smpboot: CPU 3 is now offline
> [ 4845.821409] CPU 11 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4848.710692] Broke affinity for irq 74
> [ 4848.716063] smpboot: CPU 4 is now offline
> [ 4848.721781] CPU 5 MCA banks CMCI:6 CMCI:8
> [ 4848.726440] CPU 12 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4855.990349] smpboot: CPU 5 is now offline
> [ 4855.997251] CPU 6 MCA banks CMCI:6 CMCI:8
> [ 4856.002002] CPU 13 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4859.198420] smpboot: CPU 6 is now offline
> [ 4859.205217] CPU 7 MCA banks CMCI:6 CMCI:8
> [ 4859.209858] CPU 14 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4861.202261] smpboot: CPU 7 is now offline
> [ 4861.211009] CPU 12 MCA banks CMCI:6 CMCI:8
> [ 4861.215403] CPU 15 MCA banks CMCI:2 CMCI:3 CMCI:5
> [ 4863.210557] smpboot: CPU 8 is now offline
> [ 4890.536087] divide error: 0000 [#1] SMP 
> [ 4890.540047] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf fuse loop dm_mod iTCO_wdt iTCO_vendor_support coretemp kvm_intel kvm crc32c_intel microcode cdc_ether usbnet i2c_i801 mii tpm_tis pcspkr ioatdma i7core_edac tpm serio_raw i2c_core bnx2 shpchp lpc_ich mfd_core edac_core pci_hotplug dca tpm_bios sg rtc_cmos button uhci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif edd ext3 mbcache jbd fan processor mptsas mptscsih mptbase scsi_transport_sas scsi_mod thermal thermal_sys hwmon
> [ 4890.540047] CPU 9 
> [ 4890.540047] Pid: 2243, comm: flush-8:0 Not tainted 3.6.0-rc1-tglx-hotplug-0.0.0.28.36b5ec9-default #1 IBM IBM System x -[7870C4Q]-/68Y8033     
> [ 4890.540047] RIP: 0010:[<ffffffff811276f6>]  [<ffffffff811276f6>] bdi_dirty_limit+0x66/0xc0
> [ 4890.540047] RSP: 0018:ffff8808d3e1fcc0  EFLAGS: 00010202
> [ 4890.540047] RAX: 0000000000000000 RBX: 00000000001a80c4 RCX: 28f5c28f5c28f5c3
> [ 4890.540047] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> [ 4890.540047] RBP: ffff8808d3e1fce0 R08: 0000000000000010 R09: 0000000000000000
> [ 4890.540047] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8808d3d80e20
> [ 4890.540047] R13: ffff8808d3d80e20 R14: ffff8808d3d811a0 R15: 0000000000000000
> [ 4890.540047] FS:  0000000000000000(0000) GS:ffff8808ddd40000(0000) knlGS:0000000000000000
> [ 4890.540047] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 4890.540047] CR2: ffffffffff600400 CR3: 0000000001a0c000 CR4: 00000000000007e0
> [ 4890.540047] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 4890.540047] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [ 4890.540047] Process flush-8:0 (pid: 2243, threadinfo ffff8808d3e1e000, task ffff8808d4060000)
> [ 4890.540047] Stack:
> [ 4890.540047]  0001000000000000 0000000000000000 ffff8808d3d80e20 fffffffffffffff7
> [ 4890.540047]  ffff8808d3e1fd10 ffffffff811ae95c 0000000000350189 00000000001a80c4
> [ 4890.540047]  0000000000000000 0000000000000000 ffff8808d3e1fdc0 ffffffff811b0620
> [ 4890.540047] Call Trace:
> [ 4890.540047]  [<ffffffff811ae95c>] over_bground_thresh+0x7c/0x90
> [ 4890.540047]  [<ffffffff811b0620>] wb_do_writeback+0x170/0x310
> [ 4890.540047]  [<ffffffff811b08eb>] bdi_writeback_thread+0x12b/0x420
> [ 4890.540047]  [<ffffffff811b07c0>] ? wb_do_writeback+0x310/0x310
> [ 4890.540047]  [<ffffffff8106deae>] kthread+0xde/0xf0
> [ 4890.540047]  [<ffffffff814c6184>] kernel_thread_helper+0x4/0x10
> [ 4890.540047]  [<ffffffff814bc1f0>] ? retint_restore_args+0x13/0x13
> [ 4890.540047]  [<ffffffff8106ddd0>] ? __init_kthread_worker+0x70/0x70
> [ 4890.540047]  [<ffffffff814c6180>] ? gs_change+0x13/0x13
> [ 4890.540047] Code: 28 5c 8f c2 f5 28 8b 7d e0 48 89 c6 48 0f af f3 48 c1 ee 02 48 89 f0 48 f7 e1 48 89 d6 31 d2 48 c1 ee 02 48 0f af 75 e8 48 89 f0 <48> f7 f7 41 8b 94 24 74 02 00 00 48 0f af d3 48 89 c7 48 c1 ea 
> [ 4890.540047] RIP  [<ffffffff811276f6>] bdi_dirty_limit+0x66/0xc0
> [ 4890.540047]  RSP <ffff8808d3e1fcc0>
> [ 4890.805627] ---[ end trace 3bdb61d99b220aeb ]---
> [ 4890.818925] Broke affinity for irq 76
> [ 4890.823921] smpboot: CPU 9 is now offline
> [ 4900.238238] general protection fault: 0000 [#2] SMP 
> [ 4900.242203] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf fuse loop dm_mod iTCO_wdt iTCO_vendor_support coretemp kvm_intel kvm crc32c_intel microcode cdc_ether usbnet i2c_i801 mii tpm_tis pcspkr ioatdma i7core_edac tpm serio_raw i2c_core bnx2 shpchp lpc_ich mfd_core edac_core pci_hotplug dca tpm_bios sg rtc_cmos button uhci_hcd ehci_hcd usbcore usb_common sd_mod crc_t10dif edd ext3 mbcache jbd fan processor mptsas mptscsih mptbase scsi_transport_sas scsi_mod thermal thermal_sys hwmon
> [ 4900.248087] CPU 13 
> [ 4900.248087] Pid: 0, comm: swapper/13 Tainted: G      D      3.6.0-rc1-tglx-hotplug-0.0.0.28.36b5ec9-default #1 IBM IBM System x -[7870C4Q]-/68Y8033     
> [ 4900.248087] RIP: 0010:[<ffffffff810843d7>]  [<ffffffff810843d7>] try_to_wake_up+0x57/0x2f0
> [ 4900.248087] RSP: 0018:ffff88117fd43d30  EFLAGS: 00010002
> [ 4900.248087] RAX: 6b6b6b6b6b6b6b6b RBX: 000000000000000f RCX: 000000006b6b6b6b
> [ 4900.248087] RDX: 000000006b6c6b6b RSI: ffffffff817a7fbf RDI: ffff8808d40607f0
> [ 4900.248087] RBP: ffff88117fd43d70 R08: 0000000000000002 R09: 0000000000000001
> [ 4900.248087] R10: 0000000000000000 R11: 0000000000000001 R12: ffff8808d4060000
> [ 4900.248087] R13: 000000006b6b6b6b R14: ffff8808d3d80e20 R15: 0000000000000000
> [ 4900.248087] FS:  0000000000000000(0000) GS:ffff88117fd40000(0000) knlGS:0000000000000000
> [ 4900.248087] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 4900.248087] CR2: 00007f472ef5f068 CR3: 0000000001a0c000 CR4: 00000000000007e0
> [ 4900.248087] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 4900.248087] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [ 4900.248087] Process swapper/13 (pid: 0, threadinfo ffff8808d762e000, task ffff8808d7630000)
> [ 4900.248087] Stack:
> [ 4900.248087]  0000000000000246 ffff8808d40607f0 0000000000000286 ffff8808d762ffd8
> [ 4900.248087]  ffff8808d3d80e20 ffff8808d3d811a0 ffff8808d3d80e20 ffffffff8113d970
> [ 4900.248087]  ffff88117fd43d80 ffffffff810846a0 ffff88117fd43db0 ffffffff8113da22
> [ 4900.248087] Call Trace:
> [ 4900.248087]  <IRQ> 
> [ 4900.248087]  [<ffffffff8113d970>] ? bdi_init+0x270/0x270
> [ 4900.248087]  [<ffffffff810846a0>] wake_up_process+0x10/0x20
> [ 4900.248087]  [<ffffffff8113da22>] wakeup_timer_fn+0xb2/0x1c0
> [ 4900.248087]  [<ffffffff810557db>] call_timer_fn+0xcb/0x240
> [ 4900.248087]  [<ffffffff81055710>] ? detach_if_pending+0x150/0x150
> [ 4900.248087]  [<ffffffff8113d970>] ? bdi_init+0x270/0x270
> [ 4900.248087]  [<ffffffff81056f75>] run_timer_softirq+0x1c5/0x2c0
> [ 4900.248087]  [<ffffffff8104dc79>] __do_softirq+0x159/0x400
> [ 4900.248087]  [<ffffffff814c627c>] call_softirq+0x1c/0x30
> [ 4900.248087]  [<ffffffff810044f5>] do_softirq+0x95/0xd0
> [ 4900.248087]  [<ffffffff8104d745>] irq_exit+0xe5/0x100
> [ 4900.248087]  [<ffffffff81028df9>] smp_apic_timer_interrupt+0x69/0xa0
> [ 4900.248087]  [<ffffffff814c5aef>] apic_timer_interrupt+0x6f/0x80
> [ 4900.248087]  <EOI> 
> [ 4900.248087]  [<ffffffff812db3d3>] ? intel_idle+0xc3/0x170
> [ 4900.248087]  [<ffffffff812db3d7>] ? intel_idle+0xc7/0x170
> [ 4900.248087]  [<ffffffff812db3d3>] ? intel_idle+0xc3/0x170
> [ 4900.248087]  [<ffffffff813b1937>] cpuidle_enter+0x17/0x20
> [ 4900.248087]  [<ffffffff813b1952>] cpuidle_enter_state+0x12/0x50
> [ 4900.248087]  [<ffffffff813b2403>] cpuidle_idle_call+0x133/0x260
> [ 4900.248087]  [<ffffffff8100b1f5>] cpu_idle+0x95/0xf0
> [ 4900.248087]  [<ffffffff814b1819>] start_secondary+0x85/0x8c
> [ 4900.248087] Code: 31 ed 48 89 c7 48 89 45 c8 e8 46 72 43 00 48 89 45 d0 49 8b 04 24 85 c3 0f 84 02 02 00 00 45 8b 6c 24 2c 49 8b 44 24 08 45 85 ed <44> 8b 70 18 74 75 8b 1d dd ea 9d 00 85 db 0f 85 2d 02 00 00 49 
> [ 4900.248087] RIP  [<ffffffff810843d7>] try_to_wake_up+0x57/0x2f0
> [ 4900.248087]  RSP <ffff88117fd43d30>
> [ 4900.248087] ---[ end trace 3bdb61d99b220aec ]---
> [ 4900.248087] Kernel panic - not syncing: Fatal exception in interrupt
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/