Suspend on 3.8.x-rtY (was: Re: [ANNOUNCE] 3.8.4-rt2)

[Clark Williams <williams@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 17205 bytes --]

On Thu, 25 Apr 2013 17:09:12 +0200
Sebastian Andrzej Siewior <bigeasy@linutronix.de> wrote:

> On 04/08/2013 10:25 PM, Clark Williams wrote:
> > BTW I imported -rt onto v3.8.6 with no hiccups from 'git
> > quiltimport' other than what you just fixed. Not much runtime on it
> > but it booted without complaint and ran just fine until I tried a
> > suspend/resume.
> > 
> > Resume seems to be borken on all the 3.8-rt kernels so far.
> 
> I just tested in qemu:
> - suspend to mem
>   the kvm support gives a few warn ons due to sleeping spinlocks in
>   apf_task_wake_all(). Without it, it works just fine.
> 
> - suspend to disk
>   I see very often "NOHZ: local_softirq_pending" warnings. It looks
>   like the softirq thread is going down and the timer softirq isn't
>   handled for instance. Apart from this warning I see the going into
>   suspend and waking up.

I setup a lab system with serial console to test suspend/resume. Worked
fine with the 3.8.8 F18 kernel (run pm-suspend; walk to the lab, hit
the power button, voila, resumed). Tried it with 3.8.8+rt2 and it hung.
I turned on no_console_suspend and tried again. 

When I ran pm-suspend, it suspended very quickly but coming back
in resume I got a bunch of serial console bit-rate noise and then
nothing. I could see when hitting the power switch that it was
resuming devices (hitting the CD drive, flashing various LEDs, etc.) so
I figured something else was going on. I got distracted by something
else and when I came back, the console showed resume prints and it had
succesfully resumed. I tried it again, this time with a stopwatch and
it took 9:39 to finish resuming (from the time the power button was
pressed). So something is hung and is timing out after almost 10

Here's the serial console output:

-----------------------------------------------------------------------

Fedora release 18 (Spherical Cow)
Kernel 3.8.8-rt2+ on an x86_64 (ttyS0)

rhelrt-7 login: [  510.876471] pcieport 0000:00:1c.0: System wakeup enabled by ACPI
Apr 25 15:41:47 rhelrt-7 kernel: [  510.876471] pcieport 0000:00:1c.0: System wakeup enabled by ACPI
[  511.097283] PM: Syncing filesystems ... done.
[  511.138303] PM: Preparing system for mem sleep
Apr 25 15:41:47 [  511.143388] Freezing user space processes ... rhelrt-7 kernel: [  511.097283] PM: Syncing filesystems ... done.
Apr 25 15:41:47 rhelrt-7 kernel: [  511.138303] PM: Preparing system for mem (elapsed 0.01 seconds) sleep
done.
[  511.164153] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[  511.181696] PM: Entering mem sleep
[  511.220935] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  51���\x1c�\x1c��\x1c~~����������\x1c\x1c���\x1c�\x1c\x1c��\x1c\x1c\x1c~?���\x1c��\x1c���\x1c��\x1c\x1c\x1e���\x1c\x1c\x1c\x1ep?���\x1c�|?�\x1c�\x1c��\x1c�~����������\x1c\x1c\x1c 
��\x1c�~���\x1c\x1e~��\x1c�\x1c����\x1c\x1e~�\x1c�\x1c~~?

<snip 25 lines of noise> 

 �ѥمѕ�5)�\x02���r���’���͕ɥ�����҂��\x02
                               �ѥمѕ�5r�\x02���r���ʚ���ߕɥ�����҂��\x02
                                                              �ѥمѕ�5{�	���r�������r��ٕ�Ձ�ځ�\x02\x02\x02"I5u�ە�յ����������幹rjR�[  512.759510] nouveau  [     DRM] 0xA76C: Parsing digital output script table
[  512.814213] ata7.00: configured for UDMA/33
[  512.817562] nouveau  [     DRM] 0xA7BC: Parsing digital output script table
[  512.926054] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[  512.933360] ata4: SATA link down (SStatus 0 SControl 300)
[  512.939874] ata3: SATA link down (SStatus 0 SControl 300)
[  512.946385] ata5: SATA link down (SStatus 4 SControl 300)
[  512.952860] ata2: SATA link down (SStatus 0 SControl 300)
[  513.074111] ata1.00: configured for UDMA/133
[  513.079567] sd 0:0:0:0: [sda] Starting disk
[  513.174089] firewire_core 0000:05:05.0: rediscovered device fw0
[  516.160045] 
[  516.162631] floppy driver state
[  516.166843] -------------------
[  516.171065] now=4295183467 last interrupt=4294679658 diff=503809 last called handler=reset_interrupt [floppy]
[  516.182114] timeout_message=lock fdc
[  516.186796] last output bytes:
[  516.190946]  0  0 0
[  516.194113]  0  0 0
[  516.197281]  8 80 4294679641
[  516.201244]  8 80 4294679653
[  516.205211]  8 80 4294679653
[  516.209155]  8 80 4294679653
[  516.213071]  8 80 4294679653
[  516.216960]  e 80 4294679653
[  516.220839] 13 80 4294679653
[  516.224706]  0 90 4294679653
[  516.228571] 1a 90 4294679654
[  516.232431]  0 90 4294679654
[  516.236296] 12 80 4294679654
[  516.240159]  0 90 4294679654
[  516.244036] 14 90 4294679654
[  516.247894] 18 80 4294679654
[  516.251744]  8 80 4294679658
[  516.255581]  8 80 4294679658
[  516.259407]  8 80 4294679658
[  516.263211]  8 80 4294679659
[  516.266977] last result at 4294679659
[  516.271518] last redo_fd_request at 4294679659
[  516.276842] status=0
[  516.279886] fdc_busy=1
[  516.283094] do_floppy=reset_interrupt [floppy]
[  516.288373] cont=ffffffffa01d6e00
[  516.292514] current_req=          (null)
[  516.297280] command_status=-1
[  516.301105] 
[  516.303454] floppy0: floppy timeout called
[  516.308461] PM: resume of devices complete after 3687.632 msecs
[  516.315506] PM: resume devices took 3.695 seconds
[  516.321048] PM: Finishing wakeup.
[  516.325174] Restarting tasks ... done.
Apr 25 15:43:01 rhelrt-7 kernel: [  511.143388] Freezing user space processes ... (elapsed 0.01 seconds) done.
Apr 25 15:43:01 rhelrt-7 kernel: [  511.164153] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Apr 25 15:43:01 rhelrt-7 kernel: [  511.181696] PM: Entering mem sleep
Apr 25 15:43:01 rhelrt-7 kernel: [  511.220935] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Apr 25 15:43:01 rhelrt-7 kernel: [  511.221990] serial 00:08: disabled
Apr 25 15:43:01 rhelrt-7 kernel: [  511.226701] serial 00:07: disabled
Apr 25 15:43:01 rhelrt-7 kernel: [  511.227057] sd 0:0:0:0: [sda] Stopping disk
Apr 25 15:43:01 rhelrt-7 kernel: [  511.227368] parport_pc 00:06: disabled
Apr 25 15:43:01 rhelrt-7 kernel: [  511.227586] nouveau  [     DRM] suspending fbcon...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.227799] nouveau  [     DRM] suspending display...
Apr 25 15:43:01 rhelrt-7 kernel: [  51[  516.408748] tg3 0000:0b:00.0: irq 66 for MSI/MSI-X
1.228006] nouveau  [     DRM] unpinning framebuffer(s)...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.228280] nouveau  [     DRM] evicting buffers...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.231897] nouveau  [     DRM] suspending client object trees...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.541135] PM: suspend of devices complete after 355.641 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  511.541372] PM: suspend devices took 0.356 seconds
Apr 25 15:43:01 rhelrt-7 kernel: [  511.541845] PM: late suspend of devi[  516.457258] IPv6: ADDRCONF(NETDEV_UP): em1: link is not ready
ces complete after 0.292 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  511.542387]  pci0000:00: System wakeup enabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.663104] uhci_hcd 0000:00:1d.3: System wakeup enabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.663366] uhci_hcd 0000:00:1d.2: System wakeup enabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.663614] uhci_hcd 0000:00:1d.1: System wakeup enabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.663860] uhci_hcd 0000:00:1d.0: System wakeup enabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.664236] PM: noirq suspend of devices complete after 122.136 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  511.664954] ACPI: Preparing to enter system sleep state S3
Apr 25 15:43:01 rhelrt-7 kernel: [  511.666018] PM: Saving platform NVS memory
Apr 25 15:43:01 rhelrt-7 kernel: [  511.666220] Disabling non-boot CPUs ...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.669163] smpboot: CPU 1 is now offline
Apr 25 15:43:01 rhelrt-7 kernel: [  511.671566] smpboot: CPU 2 is now offline
Apr 25 15:43:01 rhelrt-7 kernel: [  511.673056] NOHZ: local_softirq_pending 02
Apr 25 15:43:01 rhelrt-7 kernel: [  511.673096] NOHZ: local_softirq_pending 02
Apr 25 15:43:01 rhelrt-7 kernel: [  511.673114] NOHZ: local_softirq_pending 02
Apr 25 15:43:01 rhelrt-7 kernel: [  511.673134] NOHZ: local_softirq_pending 02
Apr 25 15:43:01 rhelrt-7 kernel: [  511.674370] smpboot: CPU 3 is now offline
Apr 25 15:43:01 rhelrt-7 kernel: [  511.675663] ACPI: Low-level resume complete
Apr 25 15:43:01 rhelrt-7 kernel: [  511.675663] PM: Restoring platform NVS memory
Apr 25 15:43:01 rhelrt-7 kernel: [  511.675663] Enabling non-boot CPUs ...
Apr 25 15:43:01 rhelrt-7 kernel: [  511.677781] smpboot: Booting Node 0 Processor 1 APIC 0x6
Apr 25 15:43:01 rhelrt-7 kernel: [  511.720442] CPU1 is up
Apr 25 15:43:01 rhelrt-7 kernel: [  511.725453] smpboot: Booting Node 0 Processor 2 APIC 0x1
Apr 25 15:43:01 rhelrt-7 kernel: [  511.750189] CPU2 is up
Apr 25 15:43:01 rhelrt-7 kernel: [  511.755250] smpboot: Booting Node 0 Processor 3 APIC 0x7
Apr 25 15:43:01 rhelrt-7 kernel: [  511.779877] CPU3 is up
Apr 25 15:43:01 rhelrt-7 kernel: [  511.789495] ACPI: Waking up from system sleep state S3
Apr 25 15:43:01 rhelrt-7 kernel: [  511.927190] uhci_hcd 0000:00:1d.0: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.939975] uhci_hcd 0000:00:1d.1: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.952760] uhci_hcd 0000:00:1d.2: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  511.965545] uhci_hcd 0000:00:1d.3: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  512.099089]  pci0000:00: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  512.594325] PM: noirq resume of devices complete after 788.571 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  512.607886] PM: early resume of devices complete after 0.205 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  512.620988] snd_hda_intel 0000:00:1b.0: irq 65 for MSI/MSI-X
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621094] uhci_hcd 0000:00:1d.3: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621125] ehci-pci 0000:00:1d.7: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621128] pci 0000:00:1e.0: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621132] usb usb5: root hub lost power or was reset
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621142] lpc_ich 0000:00:1f.0: rerouting interrupts for [8086:2670]
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621166] ata_piix 0000:00:1f.1: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621175] ahci 0000:00:1f.2: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621221] uhci_hcd 0000:00:1d.0: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621239] nouveau  [     DRM] re-enabling device...
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621253] usb usb2: root hub lost power or was reset
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621256] nouveau  [     DRM] resuming client object trees...
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621260] pcieport 0000:00:1c.0: System wakeup disabled by ACPI
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621271] nouveau  [   VBIOS][0000:07:00.0] running init tables
Apr 25 15:43:01 rhelrt-7 kernel: [  512.621793] ata8: port disabled--ignoring
Apr 25 15:43:01 rhelrt-7 kernel: [  512.622044] uhci_hcd 0000:00:1d.1: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.622059] uhci_hcd 0000:00:1d.2: setting latency timer to 64
Apr 25 15:43:01 rhelrt-7 kernel: [  512.622097] usb usb3: root hub lost power or was reset
Apr 25 15:43:01 rhelrt-7 kernel: [  512.622107] usb usb4: root hub lost power or was reset
Apr 25 15:43:01 rhelrt-7 kernel: [  512.630090] parport_pc 00:06: activated
Apr 25 15:43:01 rhelrt-7 kernel: [  512.634823] serial 00:07: activated
Apr 25 15:43:01 rhelrt-7 kernel: [  512.649938] serial 00:08: activated
Apr 25 15:43:01 rhelrt-7 kernel: [  512.654304] nouveau  [     DRM] resuming display...
Apr 25 15:43:01 rhelrt-7 kernel: [  512.759510] nouveau  [     DRM] 0xA76C: Parsing digital output script table
Apr 25 15:43:01 rhelrt-7 kernel: [  512.814213] ata7.00: configured for UDMA/33
Apr 25 15:43:01 rhelrt-7 kernel: [  512.817562] nouveau  [     DRM] 0xA7BC: Parsing digital output script table
Apr 25 15:43:01 rhelrt-7 kernel: [  512.926054] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Apr 25 15:43:01 rhelrt-7 kernel: [  512.933360] ata4: SATA link down (SStatus 0 SControl 300)
Apr 25 15:43:01 rhelrt-7 kernel: [  512.939874] ata3: SATA link down (SStatus 0 SControl 300)
Apr 25 15:43:01 rhelrt-7 kernel: [  512.946385] ata5: SATA link down (SStatus 4 SControl 300)
Apr 25 15:43:01 rhelrt-7 kernel: [  512.952860] ata2: SATA link down (SStatus 0 SControl 300)
Apr 25 15:43:01 rhelrt-7 kernel: [  513.074111] ata1.00: configured for UDMA/133
Apr 25 15:43:01 rhelrt-7 kernel: [  513.079567] sd 0:0:0:0: [sda] Starting disk
Apr 25 15:43:01 rhelrt-7 kernel: [  513.174089] firewire_core 0000:05:05.0: rediscovered device fw0
Apr 25 15:43:01 rhelrt-7 kernel: [  516.160045] 
Apr 25 15:43:01 rhelrt-7 kernel: [  516.162631] floppy driver state
Apr 25 15:43:01 rhelrt-7 kernel: [  516.166843] -------------------
Apr 25 15:43:01 rhelrt-7 kernel: [  516.171065] now=4295183467 last interrupt=4294679658 diff=503809 last called handler=reset_interrupt [floppy]
Apr 25 15:43:01 rhelrt-7 kernel: [  516.182114] timeout_message=lock fdc
Apr 25 15:43:01 rhelrt-7 kernel: [  516.186796] last output bytes:
Apr 25 15:43:01 rhelrt-7 kernel: [  516.190946]  0  0 0
Apr 25 15:43:01 rhelrt-7 kernel: [  516.194113]  0  0 0
Apr 25 15:43:01 rhelrt-7 kernel: [  516.197281]  8 80 4294679641
Apr 25 15:43:01 rhelrt-7 kernel: [  516.201244]  8 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.205211]  8 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.209155]  8 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.213071]  8 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.216960]  e 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.220839] 13 80 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.224706]  0 90 4294679653
Apr 25 15:43:01 rhelrt-7 kernel: [  516.228571] 1a 90 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.232431]  0 90 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.236296] 12 80 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.240159]  0 90 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.244036] 14 90 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.247894] 18 80 4294679654
Apr 25 15:43:01 rhelrt-7 kernel: [  516.251744]  8 80 4294679658
Apr 25 15:43:01 rhelrt-7 kernel: [  516.255581]  8 80 4294679658
Apr 25 15:43:01 rhelrt-7 kernel: [  516.259407]  8 80 4294679658
Apr 25 15:43:01 rhelrt-7 kernel: [  516.263211]  8 80 4294679659
Apr 25 15:43:01 rhelrt-7 kernel: [  516.266977] last result at 4294679659
Apr 25 15:43:01 rhelrt-7 kernel: [  516.271518] last redo_fd_request at 4294679659
Apr 25 15:43:01 rhelrt-7 kernel: [  516.276842] status=0
Apr 25 15:43:01 rhelrt-7 kernel: [  516.279886] fdc_busy=1
Apr 25 15:43:01 rhelrt-7 kernel: [  516.283094] do_floppy=reset_interrupt [floppy]
Apr 25 15:43:01 rhelrt-7 kernel: [  516.288373] cont=ffffffffa01d6e00
Apr 25 15:43:01 rhelrt-7 kernel: [  516.292514] current_req=          (null)
Apr 25 15:43:01 rhelrt-7 kernel: [  516.297280] command_status=-1
Apr 25 15:43:01 rhelrt-7 kernel: [  516.301105] 
Apr 25 15:43:01 rhelrt-7 kernel: [  516.303454] floppy0: floppy timeout called
Apr 25 15:43:01 rhelrt-7 kernel: [  516.308461] PM: resume of devices complete after 3687.632 msecs
Apr 25 15:43:01 rhelrt-7 kernel: [  516.315506] PM: resume devices took 3.695 seconds
Apr 25 15:43:01 rhelrt-7 kernel: [  516.321048] PM: Finishing wakeup.
Apr 25 15:43:01 rhelrt-7 kernel: [  516.325174] Restarting tasks ... done.
Apr 25 15:43:01 rhelrt-7 kernel: [  516.408748] tg3 0000:0b:00.0: irq 66 for MSI/MSI-X
Apr 25 15:43:01 rhelrt-7 kernel: [  516.457258] IPv6: ADDRCONF(NETDEV_UP): em1: link is not ready
[  519.568257] tg3 0000:0b:00.0 em1: Link is up at 1000 Mbps, full duplex
[  519.574819] tg3 0000:0b:00.0 em1: Flow control is off for TX and off for RX
[  519.581843] IPv6: ADDRCONF(NETDEV_CHANGE): em1: link becomes ready
Apr 25 15:43:04 rhelrt-7 kernel: [  519.568257] tg3 0000:0b:00.0 em1: Link is up at 1000 Mbps, full duplex
Apr 25 15:43:04 rhelrt-7 kernel: [  519.574819] tg3 0000:0b:00.0 em1: Flow control is off for TX and off for RX
Apr 25 15:43:04 rhelrt-7 kernel: [  519.581843] IPv6: ADDRCONF(NETDEV_CHANGE): em1: link becomes ready



-----------------------------------------------------------------------

I notice that nouveau is in there and yes, my laptop uses nouveau as
well. First thing I'll try is some of the pm-suspend quirks regarding graphics devices.

If that doesn't change anything I'll try swapping  out the graphics card in that test box and see
if that makes a difference. 

Clark

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 198 bytes --]