Hi!
> One for you guys on lkml ;)
It simply takes long to count pages (O(n^2) algorithm), so watchdog
triggers. I have better algorithm locally, but would like merge to
linus first. (I posted it to lkml some days ago, I can attach the
bigdiff).
Just disable the watchdog. Suspend *is* going to take time with
disabled interrupts.
Pavel
> Begin forwarded message:
>
> Date: Wed, 8 Sep 2004 09:54:09 +0200
> From: "Rafael J. Wysocki" <[email protected]>
> To: [email protected]
> Subject: 2.6.9-rc1-mm4: swsusp + AMD64 = LOCKUP on CPU0
>
>
> Sorry for posting it twice, but it seems to me that it didn't make it to the
> LKML previously:
>
> I tried the software suspend (echo 4 > /proc/acpi/sleep) on 2.6.9-rc1-mm4
> (AMD64) and it reported a LOCKUP on CPU0:
>
> Stopping tasks: ==============================|
> Freeing memory: .....................................|
> PM: Attempting to suspend to disk.
> PM: snapshotting memory.
> swsusp: critical section:
> ..<7>[nosave pfn
> 0x618].........................................................swsusp: Need
> to copy 11534 pages
> suspend: (pages needed: 11534 + 512 free: 119345)
> ..<7>[nosave pfn 0x618]...............................................NMI
> Watchdog detected LOCKUP on CPU0, registers:
> CPU 0
> Modules linked in: usbserial parport_pc lp parport joydev sg st sd_mod sr_mod
> scsi_mod nvram usbhid powernow_k8 freq_table snd_d
> Pid: 11700, comm: bash Not tainted 2.6.9-rc1-mm4
> RIP: 0010:[<ffffffff801737a4>] <ffffffff801737a4>{is_head_of_free_region+244}
> RSP: 0018:000001001482bd70 EFLAGS: 00000003
> RAX: 0000010001679080 RBX: ffffffff804ad220 RCX: 0000000000000002
> RDX: 00000100016790a8 RSI: 0000000000000030 RDI: ffffffff804ad250
> RBP: 000001000163cc08 R08: 0000000000000002 R09: 0000000000000030
> R10: 000001000140c108 R11: 0000000000000000 R12: 0000000000000004
> R13: 6db6db6db6db6db7 R14: cccccccccccccccd R15: 0000000000000000
> FS: 0000002a95d330a0(0000) GS:ffffffff805e7500(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000002a955a5000 CR3: 0000000000101000 CR4: 00000000000006e0
> Process bash (pid: 11700, threadinfo 000001001482a000, task 000001001f702270)
> Stack: cccccccccccccccd 0000000000000012 000000000001c837 000001001482bdc0
> 0000010000000000 ffffffff8016774c 0000000000002d8e ffffffff804ad220
> 000001000bf425e0 ffffffff80167cdb
> Call Trace:<ffffffff8016774c>{saveable+284}
> <ffffffff80167cdb>{suspend_prepare_image+971}
> <ffffffff802ef1ef>{pci_device_suspend+63}
> <ffffffff80167db6>{swsusp_swap_check+22}
> <ffffffff8036f9c2>{suspend_device+50}
> <ffffffff8012233c>{swsusp_arch_suspend+124}
> <ffffffff8016702c>{swsusp_suspend+12}
> <ffffffff8016837a>{pm_suspend_disk+90}
> <ffffffff80165d26>{enter_state+70}
> <ffffffff80330615>{acpi_system_write_sleep+100}
> <ffffffff8019c284>{vfs_write+228} <ffffffff8019c3c3>{sys_write+83}
> <ffffffff8011102a>{system_call+126}
>
> Code: 48 39 c5 0f 85 9b 00 00 00 48 81 3b 3c 4b 24 1d 74 1d 48 89
> console shuts up ...
>
> This is 100% reproducible and always happens in is_head_of_free_region().
>
> The .config and the output of dmesg are attached.
>
> Greets,
> RJW
>
--
On Wednesday 08 of September 2004 12:26, Pavel Machek wrote:
> Hi!
>
> > One for you guys on lkml ;)
>
> It simply takes long to count pages (O(n^2) algorithm), so watchdog
> triggers. I have better algorithm locally, but would like merge to
> linus first. (I posted it to lkml some days ago, I can attach the
> bigdiff).
>
> Just disable the watchdog. Suspend *is* going to take time with
> disabled interrupts.
Eeek. I can't disable the NMI watchdog on x86-64, can I? According to
Documentation/nmi_watchdog.txt:
"For x86-64, the needed APIC is always compiled in, and the NMI watchdog is
always enabled with I/O-APIC mode (nmi_watchdog=1)."
Greets,
RJW
--
- Would you tell me, please, which way I ought to go from here?
- That depends a good deal on where you want to get to.
-- Lewis Carroll "Alice's Adventures in Wonderland"
On Wed, 8 Sep 2004, Rafael J. Wysocki wrote:
> Eeek. I can't disable the NMI watchdog on x86-64, can I? According to
> Documentation/nmi_watchdog.txt:
>
> "For x86-64, the needed APIC is always compiled in, and the NMI watchdog is
> always enabled with I/O-APIC mode (nmi_watchdog=1)."
Try nmi_watchdog=0
Zwane
On Wednesday 08 of September 2004 14:55, Zwane Mwaikambo wrote:
> On Wed, 8 Sep 2004, Rafael J. Wysocki wrote:
>
> > Eeek. I can't disable the NMI watchdog on x86-64, can I? According to
> > Documentation/nmi_watchdog.txt:
> >
> > "For x86-64, the needed APIC is always compiled in, and the NMI watchdog
is
> > always enabled with I/O-APIC mode (nmi_watchdog=1)."
>
> Try nmi_watchdog=0
It works, thanks.
Now, I'm able to suspend the box, seemingly, but there are some problems with
resuming. There is a crash related to USB (gets "fixed" if I unload usb_ohci
etc. before suspending) and a preepmtion problem. I'll send some traces as
soon as I can get output from the serial console. In the meantime, I'll try
to compile out preemption.
Greets,
RJW
--
- Would you tell me, please, which way I ought to go from here?
- That depends a good deal on where you want to get to.
-- Lewis Carroll "Alice's Adventures in Wonderland"
On Wednesday 08 of September 2004 16:47, Rafael J. Wysocki wrote:
> On Wednesday 08 of September 2004 14:55, Zwane Mwaikambo wrote:
> > On Wed, 8 Sep 2004, Rafael J. Wysocki wrote:
[- snip -]
> > Try nmi_watchdog=0
>
> It works, thanks.
>
> Now, I'm able to suspend the box, seemingly, but there are some problems
with
> resuming. There is a crash related to USB (gets "fixed" if I unload
usb_ohci
> etc. before suspending) and a preepmtion problem. I'll send some traces as
> soon as I can get output from the serial console. In the meantime, I'll try
> to compile out preemption.
I've got the traces. First, I start the kernel with the following command
line:
root=/dev/hdc6 vga=792 resume=/dev/hdc3 nmi_watchdog=0 console=ttyS0,57600
Then, if I log in as root and do "echo 4 > /proc/acpi/sleep", it seems to
suspend successfully. However, when I press the power button and start the
kernel with the above command line, I get either this:
Relocating pagedir ....::::|
Reading image data (11699
pages): ..........................................................................................
Stopping tasks: ==|
Freeing memory: |
PM: Restoring saved image.
<7>PM: Image restored successfully.
Losing some ticks... checking if CPU frequency changed.
Warning: CPU frequency out of sync: cpufreq and timing core thinks of 800000,
is 1800000 kHz.
PCI: Setting latency timer of device 0000:00:02.0 to 64
ohci_hcd 0000:00:02.0: HC died; cleaning up
usb 1-2: USB disconnect, address 2
Badness in hcd_endpoint_disable at drivers/usb/core/hcd.c:1310
Call Trace:<ffffffffa00430bb>{:usbcore:hcd_endpoint_disable+107}
<ffffffffa0044219>{:usbcore:usb_disable_endpoint+41}<7>PCI: Setting
latency timer of device 0000:00:02.1 to 64
<ffffffffa004439a>{:usbcore:usb_disable_device+26}
<ffffffffa003fd7c>{:usbcore:usb_disconnect+188} <3>ohci_hcd
0000:00:02.1: HC died; cleaning up
<ffffffffa003fcc2>{:usbcore:usb_disconnect+2}
<ffffffffa0041c50>{:usbcore:hcd_panic+0}
<ffffffffa0041c9a>{:usbcore:hcd_panic+74}
<ffffffff801575bd>{worker_thread+733}
<ffffffff80137940>{default_wake_function+0}
<ffffffff801365c3>{__wake_up_common+67}
for the kernel with preemption compiled in (that's all I get), or this:
Relocating pagedir ....::::|
Reading image data (11543
pages): ..........................................................................................
Stopping tasks: ==|
Freeing memory: |
PM: Restoring saved image.
<7>PM: Image restored successfully.
Losing some ticks... checking if CPU frequency changed.
warning: many lost ticks.
Your time source seems to be instable or some driver is hogging interupts
rip swsusp_free+0xfe/0x1a0
Warning: CPU frequency out of sync: cpufreq and timing core thinks of 800000,
is 1800000 kHz.
PCI: Setting latency timer of device 0000:00:02.0 to 64
ohci_hcd 0000:00:02.0: HC died; cleaning up
usb 1-2: USB disconnect, address 2
Badness in hcd_endpoint_disable at drivers/usb/core/hcd.c:1310
Call Trace:<ffffffffa0041beb>{:usbcore:hcd_endpoint_disable+107}
<ffffffffa0042bb9>{:usbcore:usb_disable_endpoint+41}
<ffffffffa0042d3a>{:usbcore:usb_disable_device+26}
<ffffffffa003eb7c>{:usbcore:usb_disconnect+188}
<ffffffffa003eac2>{:usbcore:usb_disconnect+2}
<ffffffffa0040890>{:usbcore:hcd_panic+0}
<ffffffffa00408da>{:usbcore:hcd_panic+74}
<ffffffff80152742>{worker_thread+674}
<ffffffff80136930>{default_wake_function+0}
<ffffffff80134e23>{__wake_up_common+67}
<ffffffff80136930>{default_wake_function+0}
<ffffffff801524a0>{worker_thread+0} <ffffffff8015945d>{kthread+205}
<ffffffff80111673>{child_rip+8} <ffffffff80159390>{kthread+0}
<ffffffff8011166b>{child_rip+0}
Badness in hcd_endpoint_disable at drivers/usb/core/hcd.c:1310
for the kernel without preemption.
Hence, there's a problem with USB drivers, so I've repeated this experiment
with the USB drivers unloaded (except for usbcore which is always in use,
apparently), but the results haven't been much better.
Specifically, if I unload USB drivers (ie "rmmod ohci_hcd ehci_hcd usbserial
usbhid") before issuing "echo 4 > /proc/acpi/sleep", I get either this:
Relocating pagedir not necessary
Reading image data (11729
pages): ...................................................................................<1>Una
<ffffffff80178ff0>{free_block+128}
PML4 0
Oops: 0000 [1] PREEMPT
CPU 0
Modules linked in:
Pid: 3, comm: events/0 Not tainted 2.6.9-rc1-mm4
RIP: 0010:[<ffffffff80178ff0>] <ffffffff80178ff0>{free_block+128}
RSP: 0000:000001001fe39db8 EFLAGS: 00010016
RAX: 000001000105c110 RBX: 000001001ff02880 RCX: 0000010001a4e088
RDX: 0000000000000000 RSI: 0000010001a4e000 RDI: 000001001ff02880
RBP: 0000000000000000 R08: 000001001ff21010 R09: 0000000000000002
R10: 0000000000000000 R11: 0000000000000000 R12: 000001001ff02890
R13: 0000000000000008 R14: 000001001ff09010 R15: 000001001ff028b0
FS: 0000000000000000(0000) GS:ffffffff805e7500(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 0000000000101000 CR4: 00000000000006e0
Process events/0 (pid: 3, threadinfo 000001001fe38000, task 000001001fe10030)
Stack: ffffffff8049bf60 000001001ff09010 000001001ff09000 0000000000000008
000001001ff02960 000001001fc7e9b0 ffffffff805b1520 ffffffff80179146
000001001ff02880 000001001fc7e9b0
Call Trace:<ffffffff80179146>{drain_array_locked+118}
<ffffffff8017929c>{cache_reap+268}
<ffffffff80179190>{cache_reap+0} <ffffffff801575bd>{worker_thread+733}
<ffffffff80137940>{default_wake_function+0}
<ffffffff801365c3>{__wake_up_common+67}
<ffffffff80137940>{default_wake_function+0}
<ffffffff801572e0>{worker_thread+0}
<ffffffff8015eb6d>{kthread+205} <ffffffff80111afb>{child_rip+8}
<ffffffff8015eaa0>{kthread+0} <ffffffff80111af3>{child_rip+0}
Code: 48 39 32 74 0c 0f 0b 1d a9 44 80 ff ff ff ff a4 00 48 8b 06
RIP <ffffffff80178ff0>{free_block+128} RSP <000001001fe39db8>
CR2: 0000000000000000
<6>note: events/0[3] exited with preempt_count 1
................................... 11729 done.
Reading resume file was successful
PM: Preparing system for restore.
for the preemptible kernel, or this:
Relocating pagedir not necessary
Reading image data (11928
pages): ...................................................................................-------
Kernel BUG at slab:164
invalid operand: 0000 [1]
CPU 0
Modules linked in:
Pid: 3, comm: events/0 Not tainted 2.6.9-rc1-mm4
RIP: 0010:[<ffffffff80172055>] <ffffffff80172055>{free_block+133}
RSP: 0000:000001001fe39db8 EFLAGS: 00010083
RAX: 000001000105c1b8 RBX: 000001001ff02080 RCX: 0000010001a51078
RDX: 00000100010e3048 RSI: 0000010001a51040 RDI: 000001001ff02080
RBP: 0000000000000000 R08: 000001001ff24010 R09: 0000000000000002
R10: 0000000000000000 R11: 0000000000000000 R12: 000001001ff02090
R13: 000000000000000b R14: 000001001ff21010 R15: 000001001ff020b0
FS: 0000000000000000(0000) GS:ffffffff805b0500(0000) knlGS:0000000000000000
CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000004000 CR3: 0000000000101000 CR4: 00000000000006e0
Process events/0 (pid: 3, threadinfo 000001001fe38000, task 000001001fe10030)
Stack: ffffffff80464260 000001001ff21010 000001001ff21000 000000000000000b
000001001ff02160 000001001fc7e9b0 ffffffff8057a520 ffffffff801721a6
000001001fc7e9b0 000001001ff02080
Call Trace:<ffffffff801721a6>{drain_array_locked+118}
<ffffffff801722ee>{cache_reap+254}
<ffffffff801721f0>{cache_reap+0} <ffffffff80152742>{worker_thread+674}
<ffffffff80136930>{default_wake_function+0}
<ffffffff80134e23>{__wake_up_common+67}
<ffffffff80136930>{default_wake_function+0}
<ffffffff801524a0>{worker_thread+0}
<ffffffff8015945d>{kthread+205} <ffffffff80111673>{child_rip+8}
<ffffffff80159390>{kthread+0} <ffffffff8011166b>{child_rip+0}
Code: 0f 0b 75 2c 41 80 ff ff ff ff a4 00 48 8b 06 48 39 70 08 74
RIP <ffffffff80172055>{free_block+133} RSP <000001001fe39db8>
..................................... 11928 done.
Reading resume file was successful
PM: Preparing system for restore.
for the non-preemptible kernel. So, it does not work in either case, but for
different reasons.
I'm attaching the messages I get when the box is suspending (isn't the
"swsusp: Pagedir: 0 Pages" suspicious?) and the .config. Please let me know
if you need any more info. Also, if you have any patches that may help fix
this, please send them to me for testing.
Greets,
RJW
--
- Would you tell me, please, which way I ought to go from here?
- That depends a good deal on where you want to get to.
-- Lewis Carroll "Alice's Adventures in Wonderland"