Bug 88361

Summary:	snd_oxygen module doesn't wake up after suspend to ram correctly.
Product:	Drivers	Reporter:	Garik (ghost-87)
Component:	Sound(ALSA)	Assignee:	Jaroslav Kysela (perex)
Status:	NEW ---
Severity:	normal	CC:	supcry, tiwai
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	3.16.5 and further	Subsystem:
Regression:	No	Bisected commit-id:
Attachments:	Full dmesg output after suspend to ram.

Description Garik 2014-11-17 15:30:32 UTC

Xonar DG audio card (snd_oxygen kernel module) doesn't wake up after suspend to ram correctly. After waking up I have no sound at all, and I can't restart alsa manually, too:

# /etc/init.d/alsasound restart
* WARNING: you are stopping a boot service
* Storing ALSA Mixer Levels ... [ ok ]
* Restoring Mixer Levels ...

alsactl: set_control:1461: Cannot write control '2:0:0:Headphone Playback Volume:0' : Input/output error

alsactl: set_control:1461: Cannot write control '2:0:0:Headphone Playback Switch:0' : Input/output error [ ok ]


I get this error only after suspend to ram, after normal boot /etc/init.d/alsasound restart works perfectly without errors. This bug makes suspend to ram completely useless, because sound returns back only after reboot.

Comment 1 Garik 2014-11-17 15:32:11 UTC

Bug is the same on Kubuntu 12.04, Debian Sid and Gentoo Stable.

Comment 2 Takashi Iwai 2014-11-17 21:30:14 UTC

Could you check whether disabling async PM has any impact?  Run like:
  echo 0 > /sys/power/pm_async
then do S3.

Comment 3 Garik 2014-11-18 09:53:20 UTC

(In reply to Takashi Iwai from comment #2)
> Could you check whether disabling async PM has any impact?  Run like:
>   echo 0 > /sys/power/pm_async
> then do S3.

No effect. dmesg and lspci -k results are normal.

Comment 4 Takashi Iwai 2014-11-18 09:55:32 UTC

Is this a regression?  That is, did S3 ever work with this device in the past?

Comment 5 Garik 2014-11-18 10:02:43 UTC


(In reply to Takashi Iwai from comment #4)
> Is this a regression?  That is, did S3 ever work with this device in the
> past?

Sorry for misinformation. Dmesg info is unusual after waking up:

dmesg | grep snd
[  903.877350] snd_oxygen 0000:06:02.0: Refused to change power state, currently in D3
[  903.997431] snd_oxygen 0000:06:02.0: enabling device (0000 -> 0001)
[  903.998116] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1453.724455] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1453.724809] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1925.169589] snd_oxygen 0000:06:02.0: Refused to change power state, currently in D3
[ 1925.559824] snd_oxygen 0000:06:02.0: enabling device (0000 -> 0001)
[ 1925.560478] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1993.218552] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1993.218886] snd_oxygen 0000:06:02.0: oxygen: SPI wait timeout
[ 1993.219046] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219057] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219108] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219116] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219130] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219168] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219173] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219182] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219192] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1993.219198] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.225518] snd_pcm_update_hw_ptr0: 1134 callbacks suppressed
[ 1998.225525] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.230723] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.235904] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.241104] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.246283] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.251460] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.256654] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.261862] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.267043] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 1998.272219] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.240291] snd_pcm_update_hw_ptr0: 917 callbacks suppressed
[ 2003.240296] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.245470] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.250639] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.255802] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.260967] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.266140] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.271310] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.276475] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.281639] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2003.286803] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.257998] snd_pcm_update_hw_ptr0: 870 callbacks suppressed
[ 2008.258002] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.268276] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.278550] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.288842] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.299117] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.309390] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.319675] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.329949] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.340222] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2008.350494] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.280609] snd_pcm_update_hw_ptr0: 1676 callbacks suppressed
[ 2013.280616] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.281368] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.282121] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.282873] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.283626] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.284410] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.285164] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.285918] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.286673] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000
[ 2013.287446] snd_oxygen 0000:06:02.0: XRUN: , pos = 160169983, buffer size = 96000, period size = 96000

Comment 6 Garik 2014-11-18 10:04:25 UTC

(In reply to Takashi Iwai from comment #4)
> Is this a regression?  That is, did S3 ever work with this device in the
> past?

No, it's not. I joined to linux since kernel 3.13 and this bug was still here.

Comment 7 Garik 2014-11-18 10:42:09 UTC

Added full dmesg output in attachment.

Comment 8 Garik 2014-11-18 10:44:40 UTC

Created attachment 157961 [details]
Full dmesg output after suspend to ram.

Comment 9 Garik 2014-11-24 00:51:09 UTC

(In reply to Takashi Iwai from comment #4)
> Is this a regression?  That is, did S3 ever work with this device in the
> past?

The bug is still here in 3.18-rc6.

Comment 10 Garik 2014-12-17 10:47:16 UTC

S4 (hibernate) does not have this problem. This bug is almost the same like https://bugzilla.kernel.org/show_bug.cgi?id=49421. Sound card simply can't wake up after S3, it remains unpowered.

Comment 11 Garik 2014-12-31 16:27:21 UTC

Windows 7 doesn't have this problem at all, so it's probably not an BIOS or ACPI bugs.

Comment 12 supcry 2020-01-10 22:17:27 UTC

I have the same problem with my Xonar D1 after upgrading to kernel v3.4(3.6?) till now (5.4.6), Gentoo. It doesn't matter, built snd_virtuoso in kernel or as module.

After resume I see this stroke:
[66647.207500] snd_virtuoso 0000:05:00.0: Refused to change power state, currently in D3 


And then sound hangs with:
[93916.816568] snd_virtuoso 0000:05:00.0: invalid position: pcmC0D0p:0, pos = 222035967, buffer size = 88200, period size = 88200 
[93916.816573] snd_virtuoso 0000:05:00.0: invalid position: pcmC0D0p:0, pos = 222035967, buffer size = 88200, period size = 88200 
[93921.820560] snd_pcm_update_hw_ptr0: 1043 callbacks suppressed 
[93921.820567] snd_virtuoso 0000:05:00.0: invalid position: pcmC0D0p:0, pos = 222035967, buffer size = 88200, period size = 88200 
[93921.825676] snd_virtuoso 0000:05:00.0: invalid position: pcmC0D0p:0, pos = 222035967, buffer size = 88200, period size = 88200

Comment 13 supcry 2020-02-14 17:54:48 UTC

Workaround for my case is:

echo 1 > /sys/bus/pci/devices/0000\:05\:00.0/remove
echo 1 > /sys/bus/pci/rescan