Bug 23302

Summary:	alsa stops working after one or more hibernate or suspend cycles
Product:	Drivers	Reporter:	Werner Lemberg (wl)
Component:	Sound(ALSA)	Assignee:	Takashi Iwai (tiwai)
Status:	CLOSED UNREPRODUCIBLE
Severity:	high	CC:	florian, maciej.rutecki, rjw
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.36-93-pae	Subsystem:
Regression:	Yes	Bisected commit-id:
Bug Depends on:
Bug Blocks:	7216, 16444

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.