Bug 23302 - alsa stops working after one or more hibernate or suspend cycles
alsa stops working after one or more hibernate or suspend cycles
Status: CLOSED UNREPRODUCIBLE
Product: Drivers
Classification: Unclassified
Component: Sound(ALSA)
All Linux
: P1 high
Assigned To: Takashi Iwai
:
Depends on:
Blocks: 7216 16444
  Show dependency treegraph
 
Reported: 2010-11-19 16:21 UTC by Werner Lemberg
Modified: 2010-12-24 13:45 UTC (History)
3 users (show)

See Also:
Kernel Version: 2.6.36-93-pae
Tree: Mainline
Regression: Yes


Attachments

Description Werner Lemberg 2010-11-19 16:21:14 UTC
[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
Comment 1 Werner Lemberg 2010-11-23 04:41:02 UTC
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?
Comment 2 Rafael J. Wysocki 2010-11-23 22:14:08 UTC
(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.
Comment 3 Werner Lemberg 2010-11-24 07:21:49 UTC
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.
Comment 4 Werner Lemberg 2010-11-24 07:29:32 UTC
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
Comment 5 Werner Lemberg 2010-11-24 08:03:44 UTC
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.
Comment 6 Rafael J. Wysocki 2010-11-24 19:27:49 UTC
Thanks.

Please check if the problem is reproducible with this test:

# echo devices > /sys/power/pm_test
# echo disk > /sys/power/state
Comment 7 Werner Lemberg 2010-11-24 20:36:57 UTC
Yes, it's reproducible, and the logging output looks quite the same as before.
Comment 8 Rafael J. Wysocki 2010-12-05 19:47:12 UTC
What happens if you unload the sound driver before hibernation and load it
back after the resume?
Comment 9 Werner Lemberg 2010-12-06 19:02:51 UTC
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.
Comment 10 Werner Lemberg 2010-12-09 06:01:51 UTC
[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.
Comment 11 Werner Lemberg 2010-12-12 14:47:05 UTC
[2.6.37-rc5-16-pae]

The same problem with RC5.
Comment 12 Werner Lemberg 2010-12-23 08:35:17 UTC
[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.
Comment 13 Rafael J. Wysocki 2010-12-24 13:45:56 UTC
Closing as "unreproducible", since we don't know the commit that fixed
the problem.

Note You need to log in before you can comment on or make changes to this bug.