lkml.org 
[lkml]   [2012]   [Jan]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: x86/mce: machine check warning during poweroff
    On 01/14/2012 04:32 AM, Linus Torvalds wrote:

    > On Fri, Jan 13, 2012 at 12:22 PM, Srivatsa S. Bhat
    > <srivatsa.bhat@linux.vnet.ibm.com> wrote:
    >>
    >> Fundamentally, this warning is triggered during CPU Offline, which is done
    >> during poweroff, suspend, hibernate etc. IOW, even a simple
    >> # echo 0 > /sys/devices/system/cpu/cpuX/online will trigger it.
    >
    > There is definitely something wrong with CPU hotplug and MCE.
    >
    > I seem to be able to trigger not only warnings, but some oopses, by doing:
    >
    > - enable list debugging, slab debugging, and kobject debugging in the
    > kernel (I've got some other things enabled too, but I think those are
    > the main ones)
    >
    > - do
    >
    > echo 0 > /sys/devices/system/cpu/cpuX/online
    >
    > this gets a few warnings
    >
    > - then do
    >
    > echo 1 > /sys/devices/system/cpu/cpuX/online
    >
    > where bringing it up again will crash the machine entirely.
    >


    I observed this too; and it is very easy to reproduce.
    Here is the log:

    # echo 0 > /sys/devices/system/cpu/cpu1/online

    [ 65.091045] CPU 1 is now offline
    [ 65.097267] ------------[ cut here ]------------
    [ 65.102045] WARNING: at drivers/base/core.c:194 device_release+0x82/0x90()
    [ 65.109137] Hardware name: IBM System x -[7870C4Q]-
    [ 65.109139] Device 'machinecheck1' does not have a release() function, it is broken and must be fixed.
    [ 65.109141] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf microcode fuse loop dm_mod cdc_ether usbnet i7core_edac edac_core mii serio_raw i2c_i801 shpchp ioatdma iTCO_wdt iTCO_vendor_support dca pci_hotplug pcspkr bnx2 i2c_core tpm_tis tpm 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
    [ 65.109195] Pid: 6631, comm: bash Not tainted 3.2.0-debugkernel-0.0.0.28.36b5ec9-default #4
    [ 65.109197] Call Trace:
    [ 65.109202] [<ffffffff8133b462>] ? device_release+0x82/0x90
    [ 65.109208] [<ffffffff8103cc2a>] warn_slowpath_common+0x7a/0xb0
    [ 65.109212] [<ffffffff8103cd01>] warn_slowpath_fmt+0x41/0x50
    [ 65.109216] [<ffffffff8133b462>] device_release+0x82/0x90
    [ 65.109223] [<ffffffff8127051e>] ? kobj_kset_leave+0x1e/0x60
    [ 65.109228] [<ffffffff8127060d>] kobject_cleanup+0x6d/0x1b0
    [ 65.109233] [<ffffffff8127075d>] kobject_release+0xd/0x10
    [ 65.109237] [<ffffffff812704ab>] kobject_put+0x2b/0x60
    [ 65.109241] [<ffffffff8133ab42>] put_device+0x12/0x20
    [ 65.109245] [<ffffffff8133bfc5>] device_unregister+0x25/0x60
    [ 65.109252] [<ffffffff8148a22f>] mce_cpu_callback+0x149/0x1a5
    [ 65.109257] [<ffffffff8149b4a2>] notifier_call_chain+0x72/0x110
    [ 65.109263] [<ffffffff8106bf19>] __raw_notifier_call_chain+0x9/0x10
    [ 65.109270] [<ffffffff8147b9b6>] _cpu_down+0x1c6/0x320
    [ 65.109274] [<ffffffff8147bb4b>] cpu_down+0x3b/0x60
    [ 65.109279] [<ffffffff8147db1d>] store_online+0x6d/0xc8
    [ 65.109283] [<ffffffff8133a70b>] dev_attr_store+0x1b/0x20
    [ 65.109288] [<ffffffff811ecb04>] sysfs_write_file+0xd4/0x150
    [ 65.109295] [<ffffffff81176d1b>] vfs_write+0xcb/0x130
    [ 65.109299] [<ffffffff81176e70>] sys_write+0x50/0x90
    [ 65.109304] [<ffffffff814a0379>] system_call_fastpath+0x16/0x1b
    [ 65.109307] ---[ end trace dafb3fda8041063e ]---
    [ 65.112016] ------------[ cut here ]------------
    [ 65.112024] WARNING: at arch/x86/kernel/smp.c:120 native_smp_send_reschedule+0x59/0x60()
    [ 65.112027] Hardware name: IBM System x -[7870C4Q]-
    [ 65.112028] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf microcode fuse loop dm_mod cdc_ether usbnet i7core_edac edac_core mii serio_raw i2c_i801 shpchp ioatdma iTCO_wdt iTCO_vendor_support dca pci_hotplug pcspkr bnx2 i2c_core tpm_tis tpm 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
    [ 65.112067] Pid: 2277, comm: udevd Tainted: G W 3.2.0-debugkernel-0.0.0.28.36b5ec9-default #4
    [ 65.112070] Call Trace:
    [ 65.112071] <IRQ> [<ffffffff81021349>] ? native_smp_send_reschedule+0x59/0x60
    [ 65.112079] [<ffffffff8103cc2a>] warn_slowpath_common+0x7a/0xb0
    [ 65.112083] [<ffffffff8103cc75>] warn_slowpath_null+0x15/0x20
    [ 65.112086] [<ffffffff81021349>] native_smp_send_reschedule+0x59/0x60
    [ 65.112092] [<ffffffff810825f5>] trigger_load_balance+0x185/0x4f0
    [ 65.112096] [<ffffffff8108262b>] ? trigger_load_balance+0x1bb/0x4f0
    [ 65.112101] [<ffffffff81073617>] scheduler_tick+0x107/0x170
    [ 65.112107] [<ffffffff8104e057>] update_process_times+0x67/0x80
    [ 65.112113] [<ffffffff8109353f>] tick_sched_timer+0x5f/0xc0
    [ 65.112117] [<ffffffff810934e0>] ? tick_nohz_handler+0x100/0x100
    [ 65.112122] [<ffffffff8106a05e>] __run_hrtimer+0x12e/0x330
    [ 65.112126] [<ffffffff8106a4a7>] hrtimer_interrupt+0xc7/0x1f0
    [ 65.112131] [<ffffffff81022f64>] smp_apic_timer_interrupt+0x64/0xa0
    [ 65.112135] [<ffffffff814a0eb3>] apic_timer_interrupt+0x73/0x80
    [ 65.112137] <EOI> [<ffffffff8115f788>] ? __slab_alloc+0x228/0x4e0
    [ 65.112145] [<ffffffff810654f0>] ? __wake_up_bit+0x10/0x30
    [ 65.112150] [<ffffffff8110b7e5>] unlock_page+0x25/0x30
    [ 65.112157] [<ffffffff81135f75>] do_wp_page+0x4f5/0x7b0
    [ 65.112161] [<ffffffff8113708d>] handle_pte_fault+0x19d/0x1e0
    [ 65.112165] [<ffffffff81137248>] handle_mm_fault+0x178/0x2e0
    [ 65.112169] [<ffffffff8149b171>] do_page_fault+0x201/0x4c0
    [ 65.112173] [<ffffffff8103c109>] ? do_fork+0x179/0x350
    [ 65.112177] [<ffffffff8119900e>] ? mntput+0x1e/0x30
    [ 65.112182] [<ffffffff811786ef>] ? __fput+0x16f/0x210
    [ 65.112187] [<ffffffff8127ae3d>] ? trace_hardirqs_off_thunk+0x3a/0x3c
    [ 65.112192] [<ffffffff81497905>] page_fault+0x25/0x30
    [ 65.112195] ---[ end trace dafb3fda8041063f ]---
    [ 65.541793] CPU 9 MCA banks CMCI:2 CMCI:3 CMCI:5
    [ 75.472229] lockdep: fixing up alternatives.

    The above warning is related to the reschedule IPI sent to an offline cpu.
    I guess this is due to the recent changes done to nohz_balancer_kick() and
    find_new_ilb() in kernel/sched/fair.c. I had never seen this warning before
    3.3 merge window, even during CPU Hotplug stress tests. Now this warning
    is seen pretty often during CPU offline.

    [Adding Suresh Siddha and Peter Zijlstra to Cc.]

    # echo 1 > /sys/devices/system/cpu/cpu1/online

    [ 75.476772] Booting Node 0 Processor 1 APIC 0x2
    [ 75.481495] smpboot cpu 1: start_ip = 97000
    [ 75.492927] Calibrating delay loop (skipped) already calibrated this CPU
    [ 75.508449] NMI watchdog enabled, takes one hw-pmu counter.
    [ 75.515402] general protection fault: 0000 [#1] SMP
    [ 75.518940] CPU 7
    [ 75.518940] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf microcode fuse loop dm_mod cdc_ether usbnet i7core_edac edac_core mii serio_raw i2c_i801 shpchp ioatdma iTCO_wdt iTCO_vendor_support dca pci_hotplug pcspkr bnx2 i2c_core tpm_tis tpm 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
    [ 75.518940]
    [ 75.518940] Pid: 6631, comm: bash Tainted: G W 3.2.0-debugkernel-0.0.0.28.36b5ec9-default #4 IBM IBM System x -[7870C4Q]-/68Y8033
    [ 75.518940] RIP: 0010:[<ffffffff81270779>] [<ffffffff81270779>] kobject_get+0x19/0x60
    [ 75.518940] RSP: 0018:ffff8808c6cc7c18 EFLAGS: 00010206
    [ 75.518940] RAX: 0000000000000000 RBX: 6b6b6b6b6b6b6b7b RCX: 0000000000000006
    [ 75.518940] RDX: ffffffff81e98ae0 RSI: ffff8808ccc93080 RDI: 6b6b6b6b6b6b6b7b
    [ 75.518940] RBP: ffff8808c6cc7c28 R08: 5ff145670d8e439e R09: 0000000000000000
    [ 75.518940] R10: 0000000000000005 R11: 0000000000000001 R12: ffff88114ded3608
    [ 75.518940] R13: ffffffff81a13440 R14: ffff8808ddc4cb60 R15: 0000000000000001
    [ 75.518940] FS: 00007f9a3218e700(0000) GS:ffff88117fcc0000(0000) knlGS:0000000000000000
    [ 75.518940] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
    [ 75.518940] CR2: 000000000068a2a0 CR3: 000000114bd59000 CR4: 00000000000006e0
    [ 75.518940] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
    [ 75.518940] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
    [ 75.518940] Process bash (pid: 6631, threadinfo ffff8808c6cc6000, task ffff8808c6d9c600)
    [ 75.518940] Stack:
    [ 75.518940] ffff8808ccc93080 ffff88114ded3608 ffff8808c6cc7c38 ffffffff8133ab14
    [ 75.518940] ffff8808c6cc7c48 ffffffff8133ddad ffff8808c6cc7c68 ffffffff81478b82
    [ 75.518940] ffff88114ded3608 ffff8808ccc93080 ffff8808c6cc7c88 ffffffff81479062
    [ 75.518940] Call Trace:
    [ 75.518940] [<ffffffff8133ab14>] get_device+0x14/0x20
    [ 75.518940] [<ffffffff8133ddad>] klist_devices_get+0xd/0x10
    [ 75.518940] [<ffffffff81478b82>] klist_node_init+0x42/0x70
    [ 75.518940] [<ffffffff81479062>] klist_add_tail+0x22/0x60
    [ 75.518940] [<ffffffff8133e76b>] bus_add_device+0x1bb/0x200
    [ 75.518940] [<ffffffff8133c7c7>] device_add+0x2e7/0x570
    [ 75.518940] [<ffffffff813479e0>] ? device_pm_init+0x70/0xa0
    [ 75.518940] [<ffffffff8133ca69>] device_register+0x19/0x20
    [ 75.518940] [<ffffffff81489fe6>] mce_device_create+0x8b/0x18b
    [ 75.518940] [<ffffffff8148a26d>] mce_cpu_callback+0x187/0x1a5
    [ 75.518940] [<ffffffff8149b4a2>] notifier_call_chain+0x72/0x110
    [ 75.518940] [<ffffffff8106bf19>] __raw_notifier_call_chain+0x9/0x10
    [ 75.518940] [<ffffffff8148db41>] _cpu_up+0x124/0x12a
    [ 75.518940] [<ffffffff8148dc03>] cpu_up+0xbc/0x114
    [ 75.518940] [<ffffffff8147db45>] store_online+0x95/0xc8
    [ 75.518940] [<ffffffff8133a70b>] dev_attr_store+0x1b/0x20
    [ 75.518940] [<ffffffff811ecb04>] sysfs_write_file+0xd4/0x150
    [ 75.518940] [<ffffffff81176d1b>] vfs_write+0xcb/0x130
    [ 75.518940] [<ffffffff81176e70>] sys_write+0x50/0x90
    [ 75.518940] [<ffffffff814a0379>] system_call_fastpath+0x16/0x1b
    [ 75.518940] Code: ff ff 55 48 83 ef 38 48 89 e5 e8 43 fe ff ff c9 c3 90 55 48 89 e5 48 83 ec 10 48 85 ff 48 89 1c 24 4c 89 64 24 08 48 89 fb 74 0f <8b> 47 38 4c 8d 67 38 85 c0 74 1c f0 ff 43 38 48 89 d8 4c 8b 64
    [ 75.518940] RIP [<ffffffff81270779>] kobject_get+0x19/0x60
    [ 75.518940] RSP <ffff8808c6cc7c18>
    [ 75.856395] ---[ end trace dafb3fda80410640 ]---


    And in a separate try, I got this during cpu online operation:
    (Pretty much the same as above, but with the BUG description present.)

    [ 83.491328] Booting Node 1 Processor 6 APIC 0x14^M
    [ 83.496135] smpboot cpu 6: start_ip = 97000^M
    [ 72.494772] Calibrating delay loop (skipped) already calibrated this CPU^M
    [ 83.522491] NMI watchdog enabled, takes one hw-pmu counter.^M
    [ 83.529016] BUG: unable to handle kernel paging request at 000000350000004a^M
    [ 83.532868] IP: [<ffffffff8126cac9>] kobject_get+0x19/0x60^M
    [ 83.532868] PGD 8c7909067 PUD 0 ^M
    [ 83.532868] Oops: 0000 [#1] SMP ^M
    [ 83.532868] CPU 0 ^M
    [ 83.532868] Modules linked in: ipv6 cpufreq_conservative cpufreq_userspace cpufreq_powersave acpi_cpufreq mperf microcode fuse loop dm_mod ioatdma cdc_ether usbnet bnx2 shpchp mii tpm_tis tpm i7core_edac rtc_cmos serio_raw i2c_i801 dca pcspkr pci_hotplug edac_core i2c_core iTCO_wdt iTCO_vendor_support sg tpm_bios 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^M
    [ 83.532868] ^M
    [ 83.532868] Pid: 6347, comm: allon_cpu_statu Tainted: G W 3.2.0-33-default #3 IBM IBM System x -[7870C4Q]-/68Y8033 ^M
    [ 83.532868] RIP: 0010:[<ffffffff8126cac9>] [<ffffffff8126cac9>] kobject_get+0x19/0x60^M
    [ 83.532868] RSP: 0018:ffff8808c78c1c18 EFLAGS: 00010206^M
    [ 83.532868] RAX: 0000000000000000 RBX: 0000003500000012 RCX: 0000000000000006^M
    [ 83.532868] RDX: ffffffff81f0f180 RSI: ffff8808c7f01118 RDI: 0000003500000012^M
    [ 83.532868] RBP: ffff8808c78c1c28 R08: 543148780dbe0391 R09: 0000000000000000^M
    [ 83.532868] R10: 0000000000000005 R11: 0000000000000001 R12: ffff8808c9f37d38^M
    [ 83.532868] R13: ffffffff81a13440 R14: ffff88117fc8cb60 R15: 0000000000000006^M
    [ 83.532868] FS: 00007f7043861700(0000) GS:ffff8808ffc00000(0000) knlGS:0000000000000000^M
    [ 83.532868] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b^M
    [ 83.532868] CR2: 000000350000004a CR3: 00000008c7ee9000 CR4: 00000000000006f0^M
    [ 83.532868] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000^M
    [ 83.532868] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400^M
    [ 83.532868] Process allon_cpu_statu (pid: 6347, threadinfo ffff8808c78c0000, task ffff8808ca7c8bc0)^M
    [ 83.532868] Stack:^M
    [ 83.532868] ffff8808c7f01118 ffff8808c9f37d38 ffff8808c78c1c38 ffffffff813362e4^M
    [ 83.532868] ffff8808c78c1c48 ffffffff8133951d ffff8808c78c1c68 ffffffff81473db2^M
    [ 83.532868] ffff8808c9f37d38 ffff8808c7f01118 ffff8808c78c1c88 ffffffff81474292^M
    [ 83.532868] Call Trace:^M
    [ 83.532868] [<ffffffff813362e4>] get_device+0x14/0x20^M
    [ 83.532868] [<ffffffff8133951d>] klist_devices_get+0xd/0x10^M
    [ 83.532868] [<ffffffff81473db2>] klist_node_init+0x42/0x70^M
    [ 83.532868] [<ffffffff81474292>] klist_add_tail+0x22/0x60^M
    [ 83.532868] [<ffffffff81339edb>] bus_add_device+0x1bb/0x200^M
    [ 83.532868] [<ffffffff81337f77>] device_add+0x2e7/0x570^M
    [ 83.532868] [<ffffffff81343080>] ? device_pm_init+0x70/0xa0^M
    [ 83.532868] [<ffffffff81338219>] device_register+0x19/0x20^M
    [ 83.532868] [<ffffffff8148537f>] mce_device_create+0x8b/0x18b^M
    [ 83.532868] [<ffffffff81485606>] mce_cpu_callback+0x187/0x1a5^M
    [ 83.532868] [<ffffffff81496db2>] notifier_call_chain+0x72/0x110^M
    [ 83.532868] [<ffffffff8106c1c9>] __raw_notifier_call_chain+0x9/0x10^M
    [ 83.532868] [<ffffffff81488dc1>] _cpu_up+0x124/0x12a^M
    [ 83.532868] [<ffffffff81488e83>] cpu_up+0xbc/0x114^M
    [ 83.532868] [<ffffffff81479065>] store_online+0x95/0xc8^M
    [ 83.532868] [<ffffffff81335edb>] dev_attr_store+0x1b/0x20^M
    [ 83.532868] [<ffffffff811e9214>] sysfs_write_file+0xd4/0x150^M
    [ 83.532868] [<ffffffff81173aeb>] vfs_write+0xcb/0x130^M
    [ 83.532868] [<ffffffff81173c40>] sys_write+0x50/0x90^M
    [ 83.532868] [<ffffffff8149bc39>] system_call_fastpath+0x16/0x1b^M
    [ 83.532868] Code: ff ff 55 48 83 ef 38 48 89 e5 e8 43 fe ff ff c9 c3 90 55 48 89 e5 48 83 ec 10 48 85 ff 48 89 1c 24 4c 89 64 24 08 48 89 fb 74 0f <8b> 47 38 4c 8d 67 38 85 c0 74 1c f0 ff 43 38 48 89 d8 4c 8b 64 ^M
    [ 83.532868] RIP [<ffffffff8126cac9>] kobject_get+0x19/0x60^M
    [ 83.532868] RSP <ffff8808c78c1c18>^M
    [ 83.532868] CR2: 000000350000004a^M
    [ 83.890209] ---[ end trace fab5021066ee998d ]---^M


    > so it's definitely something bad in MCE device handling, and probably
    > something to do with reusing a 'struct device' after freeign it, or
    > after not having completely cleaned it up.
    >
    > I didn't see if I could spot the problem, but I think this is entirely
    > reproducible, so hopefully somebody who knows the MCE code can
    > trivially see this and fix it.
    >
    > Linus
    >


    Regards,
    Srivatsa S. Bhat
    IBM Linux Technology Center



    \
     
     \ /
      Last update: 2012-01-14 00:31    [W:0.039 / U:59.744 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site