[openSuSE factory] This problem always happens after two or three hibernation cycles; with suspend, it only happens occasionally. If the problem occurs, calling mplayer on the command line with a simple audio file shows this: [AO OSS] audio_setup: Can't open audio device /dev/dsp: Permission denied [AO_ALSA] alsa-lib: confmisc.c:768:(parse_card) cannot find card '0' [AO_ALSA] alsa-lib: conf.c:4184:(_snd_config_evaluate) function snd_func_card_driver returned error: Permission denied [AO_ALSA] alsa-lib: confmisc.c:392:(snd_func_concat) error evaluating strings [AO_ALSA] alsa-lib: conf.c:4184:(_snd_config_evaluate) function snd_func_concat returned error: Permission denied [AO_ALSA] alsa-lib: confmisc.c:1251:(snd_func_refer) error evaluating name [AO_ALSA] alsa-lib: conf.c:4184:(_snd_config_evaluate) function snd_func_refer returned error: Permission denied [AO_ALSA] alsa-lib: conf.c:4663:(snd_config_expand) Evaluate error: Permission denied [AO_ALSA] alsa-lib: pcm.c:2208:(snd_pcm_open_noupdate) Unknown PCM default [AO_ALSA] Playback open error: Permission denied and the file doesn't get played; mplayer kind of stops (but can be cancelled with ^C). This is a regression not seen with older kernels. I think I've seen it first with 2.6.36-rc4, but I'm not sure. Note that this problem seems to disable KDE to start a reboot or shutdown – it waits forever (and no `plong' is heard). My audio setup is registered here: http://www.alsa-project.org/db/?f=552b9eff5f4bdab7420a3c8f50b9b90e41a0c44b I've called alsa-info.sh while the above described problem is active. PS: I've also reported this (with a slightly older kernel) as https://bugtrack.alsa-project.org/alsa-bug/view.php?id=5164
With kernel-pae 2.6.37-rc2.1.2, the problem happens much more often with suspend. It's *really* annoying now. Any idea how to circumvent the problem? It would be nice to get any comment... BTW, shall I update the `Kernel Version' field if the problem happens with newer kernels too?
(In reply to comment #1) > With kernel-pae 2.6.37-rc2.1.2, the problem happens much more often with > suspend. It's *really* annoying now. > > Any idea how to circumvent the problem? It would be nice to get any > comment... Sorry, I've been busy recently and I don't really have an idea of what the problem may be. Can you reproduce the problem with the following test: # echo core > /sys/power/pm_test # echo disk > /sys/power/state (it should simulate the preparations to hibernate and return to the command prompt in 5-10 sec.)? > BTW, shall I update the `Kernel Version' field if the problem happens with > newer kernels too? Please don't. It's better to know when the problem _started_ to occur.
I can reproduce it. The first time I've executed # echo core > /sys/power/pm_test; echo disk > /sys/power/state I got the problem.
For completeness, here the relevant parts from /var/log/messages for the above action. kernel: [ 386.272634] PM: Marking nosave pages: 000000000009f000 - 0000000000100000 kernel: [ 386.272642] PM: Basic memory bitmaps created acpid: client 1976[0:0] has disconnected kernel: [ 386.272644] PM: Syncing filesystems ... done. kernel: [ 387.180383] Freezing user space processes ... (elapsed 0.01 seconds) done. kernel: [ 387.196064] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. kernel: [ 387.212081] PM: Preallocating image memory... done (allocated 154429 pages) kernel: [ 393.836971] PM: Allocated 617716 kbytes in 6.62 seconds (93.31 MB/s) kernel: [ 393.836975] Suspending console(s) (use no_console_suspend to debug) kernel: [ 393.837649] b44 ssb0:0: eth0: powering down PHY kernel: [ 393.852141] usb 5-1: Disconnecting SN9C1xx PC Camera... kernel: [ 393.852145] usb 5-1: V4L2 device video0 deregistered kernel: [ 393.853481] ACPI handle has no context! kernel: [ 393.853490] sdhci-pci 0000:03:01.1: PCI INT B disabled rtkit-daemon[3182]: The canary thread is apparently starving. Taking action. rtkit-daemon[3182]: Demoting known real-time threads. kernel: [ 393.853497] ACPI handle has no context! kernel: [ 393.853653] b44 0000:03:00.0: PCI INT A disabled kernel: [ 393.853660] ACPI handle has no context! kernel: [ 394.056020] sd 0:0:0:0: [sda] Synchronizing SCSI cache kernel: [ 394.056374] ata_piix 0000:00:1f.2: PCI INT B disabled kernel: [ 394.060107] HDA Intel 0000:00:1b.0: PCI INT A disabled kernel: [ 394.076048] PM: freeze of devices complete after 238.697 msecs kernel: [ 394.076498] PM: late freeze of devices complete after 0.444 msecs acpid: client connected from 1976[0:0] rtkit-daemon[3182]: Demoted 0 threads. kernel: [ 394.076805] ACPI: Preparing to enter system sleep state S4 kernel: [ 394.078861] PM: Saving platform NVS memory kernel: [ 394.078865] Disabling non-boot CPUs ... kernel: [ 394.079160] Unmapping cpu 1 from all nodes kernel: [ 394.080317] CPU 1 is now offline kernel: [ 394.080321] SMP alternatives: switching to UP code kernel: [ 394.089866] hibernation debug: Waiting for 5 seconds. kernel: [ 394.092006] Enabling non-boot CPUs ... kernel: [ 394.092006] SMP alternatives: switching to SMP code acpid: 1 client rule loaded kernel: [ 394.098501] Booting Node 0 Processor 1 APIC 0x1 kernel: [ 394.089345] Initializing CPU#1 kernel: [ 394.089345] Mapping cpu 1 to node 0 kernel: [ 394.188542] NMI watchdog enabled, takes one hw-pmu counter. kernel: [ 394.192068] CPU1 is up kernel: [ 394.192484] ACPI: Waking up from system sleep state S4 kernel: [ 394.212039] HDA Intel 0000:00:1b.0: BAR 0: set to [mem 0xefebc000-0xefebffff 64bit] (PCI address [0xefebc000-0xefebffff]) kernel: [ 394.212061] HDA Intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x100, writing 0x10a) kernel: [ 394.212084] HDA Intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10) kernel: [ 394.212092] HDA Intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100102) kernel: [ 394.212487] ata_piix 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b80001, writing 0x2b80005) kernel: [ 394.228044] iwl3945 0000:0b:00.0: BAR 0: set to [mem 0xefdff000-0xefdfffff] (PCI address [0xefdff000-0xefdfffff]) kernel: [ 394.228108] iwl3945 0000:0b:00.0: restoring config space at offset 0xf (was 0x100, writing 0x104) kernel: [ 394.228192] iwl3945 0000:0b:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100506) kernel: [ 394.228336] b44 0000:03:00.0: restoring config space at offset 0x1 (was 0x100102, writing 0x100106) kernel: [ 394.244029] firewire_ohci 0000:03:01.0: BAR 0: set to [mem 0xef9fd800-0xef9fdfff] (PCI address [0xef9fd800-0xef9fdfff]) kernel: [ 394.244062] firewire_ohci 0000:03:01.0: restoring config space at offset 0x3 (was 0x800000, writing 0x804000) kernel: [ 394.244070] firewire_ohci 0000:03:01.0: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106) kernel: [ 394.260030] sdhci-pci 0000:03:01.1: BAR 0: set to [mem 0xef9fd500-0xef9fd5ff] (PCI address [0xef9fd500-0xef9fd5ff]) kernel: [ 394.260062] sdhci-pci 0000:03:01.1: restoring config space at offset 0x3 (was 0x800000, writing 0x804000) kernel: [ 394.260071] sdhci-pci 0000:03:01.1: restoring config space at offset 0x1 (was 0x2100000, writing 0x2100106) kernel: [ 394.260222] PM: early restore of devices complete after 62.329 msecs kernel: [ 394.304027] i915 0000:00:02.0: setting latency timer to 64 kernel: [ 394.306000] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 21 (level, low) -> IRQ 21 kernel: [ 394.306011] HDA Intel 0000:00:1b.0: setting latency timer to 64 kernel: [ 394.306067] HDA Intel 0000:00:1b.0: irq 40 for MSI/MSI-X kernel: [ 394.306114] pci 0000:00:1c.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 kernel: [ 394.306120] pci 0000:00:1c.0: setting latency timer to 64 kernel: [ 394.306130] pci 0000:00:1c.3: PCI INT D -> GSI 19 (level, low) -> IRQ 19 kernel: [ 394.306135] pci 0000:00:1c.3: setting latency timer to 64 kernel: [ 394.306145] uhci_hcd 0000:00:1d.0: setting latency timer to 64 kernel: [ 394.306190] usb usb2: root hub lost power or was reset kernel: [ 394.306205] uhci_hcd 0000:00:1d.1: setting latency timer to 64 kernel: [ 394.306248] usb usb3: root hub lost power or was reset kernel: [ 394.306262] uhci_hcd 0000:00:1d.2: setting latency timer to 64 kernel: [ 394.306304] usb usb4: root hub lost power or was reset kernel: [ 394.306318] uhci_hcd 0000:00:1d.3: setting latency timer to 64 kernel: [ 394.306361] usb usb5: root hub lost power or was reset kernel: [ 394.306378] ehci_hcd 0000:00:1d.7: setting latency timer to 64 kernel: [ 394.306406] usb usb1: root hub lost power or was reset kernel: [ 394.310306] ehci_hcd 0000:00:1d.7: cache line size of 64 is not supported kernel: [ 394.310320] pci 0000:00:1e.0: setting latency timer to 64 kernel: [ 394.310335] ata_piix 0000:00:1f.2: PCI INT B -> GSI 17 (level, low) -> IRQ 17 kernel: [ 394.310341] ata_piix 0000:00:1f.2: setting latency timer to 64 kernel: [ 394.310395] b44 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 kernel: [ 394.310478] sdhci-pci 0000:03:01.1: PCI INT B -> GSI 18 (level, low) -> IRQ 18 kernel: [ 394.311510] sd 0:0:0:0: [sda] Starting disk kernel: [ 394.312494] ata2.00: _GTF evaluation failed (AE 0x1001) kernel: [ 394.372138] firewire_core: skipped bus generations, destroying all nodes kernel: [ 394.476690] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out kernel: [ 394.492426] ata1.00: configured for UDMA/100 kernel: [ 394.492466] ata2.00: configured for UDMA/33 kernel: [ 394.784068] usb 5-1: reset full speed USB device using uhci_hcd and address 2 kernel: [ 394.872070] firewire_core: rediscovered device fw0 kernel: [ 394.953760] PM: restore of devices complete after 650.852 msecs kernel: [ 394.955705] usb 5-1: SN9C120 PC Camera Controller detected (vid:pid 0x0C45:0x613B) kernel: [ 395.072709] usb 5-1: OV7660 image sensor detected kernel: [ 395.866696] usb 5-1: Initialization succeeded kernel: [ 395.866803] usb 5-1: V4L2 device registered as video0 kernel: [ 395.866805] usb 5-1: Optional device control through 'sysfs' interface disabled kernel: [ 395.867078] PM: Image restored successfully. kernel: [ 395.867080] Restarting tasks ... done. kernel: [ 395.870319] PM: Basic memory bitmaps freed kernel: [ 395.870328] video LNXVIDEO:01: Restoring backlight state kernel: [ 397.988222] b44 ssb0:0: eth0: Link is up at 100 Mbps, full duplex kernel: [ 397.988231] b44 ssb0:0: eth0: Flow control is off for TX and off for RX
Another remark: I've similar problems with HAL which sometimes fails after suspend, and it is not possible to fix it by calling `/etc/rc.d/haldaemon restart'. Symptoms are that e.g. k3b can't recognize the optical disk, or that mounting a USB stick with the KDE device monitor fails. However, this doesn't happen as often as with my sound system, and I can't remember whether the problems have appeared at the same time. I just want to mention it since there is possibly a connection.
Thanks. Please check if the problem is reproducible with this test: # echo devices > /sys/power/pm_test # echo disk > /sys/power/state
Yes, it's reproducible, and the logging output looks quite the same as before.
What happens if you unload the sound driver before hibernation and load it back after the resume?
Currently, I can't test since I'm not able to boot 2.6.37-rc3; somehow my graphics card (intel 945GM) hangs. I have to wait until openSuSE publishes an rc4 kernel.
[kernel-pae 2.6.37-rc4.12.1] Accidentally, RC4 has booted inspite of the graphics card problem, so I've just tested the sound card problem by doing /etc/rc.d/alsasound unload before doing `pm-suspend', and /etc/rc.d/alsasound reload after resuming. The first time it has worked, but the second time it has failed in the above described way.
[2.6.37-rc5-16-pae] The same problem with RC5.
[openSuSE kernel-pae 2.6.37-12.2, git 149d22bc (branch master)] [openSuSE alsa 1.0.23-10.1] It seems to be back to normal with this kernel, which I currently use. Up to now, both suspend to RAM and suspend to disk seem not to make audio output fail.
Closing as "unreproducible", since we don't know the commit that fixed the problem.