hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000
A message that is not in the archive (sent off-list or not yet received): [email protected]
Hi Petr,
Petr Baudis wrote[1]:
Quoted 1 line
Version: 3.1.5-1
[...]
Quoted 4 lines
this bug is twofold - I'm not sure which of the two problems is the real culprit of the issue I'm seeing, and if it's worth fixing both or just either one. It boils down to sometimes choppy playback and mainly applications getting stuck on some audio operations.
[...]
Quoted 1 line
This did not use to happen at least back around 2.6.32.
[...]
Quoted 2 lines
I'd be willing to do some bisecting if people believe it would make sense.
I don't see any relevant newer fixes, but could you test the for-next branch from [2] anyway? Output from the alsa-info.sh script[3] would also be useful.
Some snippets from the original report kept below, in case someone from the alsa project has ideas. (The unabridged report is at [1].)
Thanks and hope that helps,
Jonathan
[1] http://bugs.debian.org/653524
[2] git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound.git
[3] http://www.alsa-project.org/alsa-info.sh
Quoted 42 lines
(i) hda-intel on my motherboard is sensitive to changing volume during playback. If I start playback (e.g. mplayer) and start changing volume levels in alsamixer wildly, in a few seconds the playback will stutter for a bit and
hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000gets logged.
(ii) After this happens, the playback will get slightly choppy, but that is barely ever noticeable. The real issue is that applications will get stuck on some audio operations - most notably, when mplayer stops playing a song, it will do
SNDCTL_DSP_SYNC:03:52:14.774972 ioctl(4, SNDCTL_DSP_SYNC, 0) = ? ERESTARTSYS (To be restarted) 03:52:16.813873 --- SIGINT (Interrupt) @ 0 (0) --- 03:52:16.814479 write(2, "\n", 1) = 1 03:52:16.821637 write(2, "\nMPlayer interrupted by signal 2"..., 54) = 54 03:52:16.835238 rt_sigreturn(0x29) = 16 03:52:16.835348 ioctl(4, SNDCTL_DSP_SYNC, 0) = ? ERESTARTSYS (To be restarted) 03:52:18.393655 --- SIGINT (Interrupt) @ 0 (0) --- 03:52:18.393782 write(2, "\n", 1) = 1 03:52:18.400725 write(2, "\nMPlayer interrupted by signal 2"..., 54) = 54 03:52:18.415261 close(4294967295) = -1 EBADF (Bad file descriptor) 03:52:18.416276 exit_group(1) = ?When in the polling mode, *sometimes* the
SNDCTL_DSP_SYNCwill hang indefinitely. I suspect this also causes my Flash sound playback to break, but I do not have that confirmed 100%.Removing the snd-intel-hda module and re-modprobing it will fix the issue until next time the volume adjustment causes a switch to the polling mode.
This did not use to happen at least back around 2.6.32. These kernel versions had different issue with this particular chipset and mapping DMA space above 4GiB boundary with >4GiB RAM installed, though. Not sure if this bug does not have something still to do with that (though similar symptoms disappeared for the network card).
I'd be willing to do some bisecting if people believe it would make sense.
[...]
Quoted 27 lines
[2174402.896629] snd_hda_intel 0000:01:00.1: PCI INT B disabled [2174402.924482] snd_hda_intel 0000:00:14.2: PCI INT A disabled [2174405.457990] snd_hda_intel 0000:00:14.2: PCI INT A -> GSI 16 (level, low) -> IRQ 16 [2174405.458166] snd_hda_intel 0000:00:14.2: irq 43 for MSI/MSI-X [2174405.852109] hda_codec: AD1988: BIOS auto-probing. [2174405.852420] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:14.2/input/input10 [2174405.877935] snd_hda_intel 0000:01:00.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19 [2174405.878113] snd_hda_intel 0000:01:00.1: irq 44 for MSI/MSI-X [2174405.878166] snd_hda_intel 0000:01:00.1: setting latency timer to 64 [2174405.892565] HDMI status: Codec=0 Pin=3 Presence_Detect=0 ELD_Valid=0 [2174405.893243] input: HDA ATI HDMI HDMI/DP as /devices/pci0000:00/0000:00:02.0/0000:01:00.1/sound/card2/input11 [2175405.280022] hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000 <rmmod snd-intel-hda> [2175808.496464] snd_hda_intel 0000:01:00.1: PCI INT B disabled [2175808.528486] snd_hda_intel 0000:00:14.2: PCI INT A disabled <modprobe snd-intel-hda> [2175811.100597] snd_hda_intel 0000:00:14.2: PCI INT A -> GSI 16 (level, low) -> IRQ 16 [2175811.100774] snd_hda_intel 0000:00:14.2: irq 43 for MSI/MSI-X [2175811.496115] hda_codec: AD1988: BIOS auto-probing. [2175811.496406] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:14.2/input/input12 [2175811.513015] snd_hda_intel 0000:01:00.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19 [2175811.513199] snd_hda_intel 0000:01:00.1: irq 44 for MSI/MSI-X [2175811.513256] snd_hda_intel 0000:01:00.1: setting latency timer to 64 [2175811.533844] HDMI status: Codec=0 Pin=3 Presence_Detect=0 ELD_Valid=0 [2175811.534515] input: HDA ATI HDMI HDMI/DP as /devices/pci0000:00/0000:00:02.0/0000:01:00.1/sound/card2/input13 <twiddling volume controls in alsamixer> [2175932.840016] hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000
[...]
Quoted 5 lines
bios_vendor: American Megatrends Inc.bios_version: 1009board_vendor: ASUSTeK Computer INC.board_name: M2R32-MVPboard_version: Rev 1.xx
[...]
Quoted 9 lines
00:14.2 Audio device [0403]: ATI Technologies Inc SBx00 Azalia (Intel HDA) [1002:4383]
Subsystem: ATI Technologies Inc SBx00 Azalia (Intel HDA) [1002:4383]
Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=slow >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
Latency: 64, Cache Line Size: 64 bytes
Interrupt: pin A routed to IRQ 43
Region 0: Memory atfbcf0000(64-bit, non-prefetchable) [size=16K]
Capabilities: <access denied>
Kernel driver in use:snd_hda_intel
Hi!
Quoted 9 lines · Jonathan Nieder
Petr Baudis wrote[1]:
Quoted 1 line
Version: 3.1.5-1
[...]
Quoted 4 lines
this bug is twofold - I'm not sure which of the two problems is the real culprit of the issue I'm seeing, and if it's worth fixing both or just either one. It boils down to sometimes choppy playback and mainly applications getting stuck on some audio operations.
[...]
Quoted 8 lines
Quoted 1 line
This did not use to happen at least back around 2.6.32.
[...]
Quoted 2 lines
I'd be willing to do some bisecting if people believe it would make sense.
I don't see any relevant newer fixes, but could you test the for-next branch from [2] anyway? Output from the
alsa-info.shscript[3] would also be useful.
I'm really sorry for taking so long - this is still an issue for me, but contrary to my expectations, I was not able to reboot this machine yet and it might take some more time (weeks...) before that's convenient. I will try the then-current kernel and for-next branch then.
The output from the alsa-info.sh script is at:
http://www.alsa-project.org/db/?f=184928832b33b23c68d17460604b9a37af0fac4b
Signature · 3 lines
Petr "Pasky" Baudis The goal of Computer Science is to build something that will last at least until we've finished building it.
At Sat, 21 Jan 2012 10:16:02 +0100,
Quoted 22 lines · Petr Baudis
Hi!
Quoted 9 lines · Jonathan Nieder
Petr Baudis wrote[1]:
Quoted 1 line
Version: 3.1.5-1
[...]
Quoted 4 lines
this bug is twofold - I'm not sure which of the two problems is the real culprit of the issue I'm seeing, and if it's worth fixing both or just either one. It boils down to sometimes choppy playback and mainly applications getting stuck on some audio operations.
[...]
Quoted 8 lines
Quoted 1 line
This did not use to happen at least back around 2.6.32.
[...]
Quoted 2 lines
I'd be willing to do some bisecting if people believe it would make sense.
I don't see any relevant newer fixes, but could you test the for-next branch from [2] anyway? Output from the
alsa-info.shscript[3] would also be useful.
Quoted 8 lines
I'm really sorry for taking so long - this is still an issue for me, but contrary to my expectations, I was not able to reboot this machine yet and it might take some more time (weeks...) before that's convenient. I will try the then-current kernel and for-next branch then.
The output from the
alsa-info.shscript is at:http://www.alsa-project.org/db/?f=184928832b33b23c68d17460604b9a37af0fac4b
Thanks. Switching to the polling mode is really harmless. So, basically you can ignore these messages. I can change it only as a debug message.
OTOH, if the switching to single_cmd mode happens, this is a serious problem. But, as far as I see in alsa-info.sh output, it didn't happen.
Takashi
Quoted 7 lines · Takashi Iwai
Thanks. Switching to the polling mode is really harmless. So, basically you can ignore these messages. I can change it only as a debug message.
OTOH, if the switching to
single_cmdmode happens, this is a serious problem. But, as far as I see inalsa-info.shoutput, it didn't happen.
Ok, then the bug is in handling of polling mode in this particular chip. After such switch to polling mode, applications will get stuck on releasing the soundcard. Another symptom I forgot to describe is that the last ~100ms of output will keep repeating when I pause/stop playback, one has to mute the volume to get rid of this. Again, this starts happenning only sometimes after the switch to polling mode, but then keeps happenning fairly consistently.
Signature · 3 lines
Petr "Pasky" Baudis The goal of Computer Science is to build something that will last at least until we've finished building it.
At Mon, 23 Jan 2012 10:46:30 +0100,
Quoted 6 lines · Petr Baudis
Quoted 4 lines · Takashi Iwai
Thanks. Switching to the polling mode is really harmless. So, basically you can ignore these messages. I can change it only as a debug message.
Quoted 7 lines
Quoted 3 lines
OTOH, if the switching to
single_cmdmode happens, this is a serious problem. But, as far as I see inalsa-info.shoutput, it didn't happen.Ok, then the bug is in handling of polling mode in this particular chip. After such switch to polling mode, applications will get stuck on releasing the soundcard.
What do you mean "releasing the soundcard"? Closing the PCM stream, or unloading the module, or at shutdown?
Quoted 5 lines
Another symptom I forgot to describe is that
the last ~100ms of output will keep repeating when I pause/stop playback, one has to mute the volume to get rid of this. Again, this starts happenning only sometimes after the switch to polling mode, but then keeps happenning fairly consistently.
Hm, this sounds like some interrupt issue, then. After all, switching to the polling-mode happens because the expected interrupt didn't arrive in time. If a similar problem happens in the PCM stream, too, it might be some other generic interrupt problem.
thanks,
Takashi
Quoted 12 lines · Takashi Iwai
At Mon, 23 Jan 2012 10:46:30 +0100,
Quoted 10 lines · Petr Baudis
Quoted 7 lines · Takashi Iwai
Thanks. Switching to the polling mode is really harmless. So, basically you can ignore these messages. I can change it only as a debug message.
OTOH, if the switching to
single_cmdmode happens, this is a serious problem. But, as far as I see inalsa-info.shoutput, it didn't happen.
Quoted 6 lines
Quoted 3 lines
Ok, then the bug is in handling of polling mode in this particular chip. After such switch to polling mode, applications will get stuck on releasing the soundcard.
What do you mean "releasing the soundcard"? Closing the PCM stream, or unloading the module, or at shutdown?
Closing the PCM stream - see strace snippet in the original post.
Quoted 10 lines
Quoted 5 lines
Another symptom I forgot to describe is that
the last ~100ms of output will keep repeating when I pause/stop playback, one has to mute the volume to get rid of this. Again, this starts happenning only sometimes after the switch to polling mode, but then keeps happenning fairly consistently.Hm, this sounds like some interrupt issue, then. After all, switching to the polling-mode happens because the expected interrupt didn't arrive in time. If a similar problem happens in the PCM stream, too, it might be some other generic interrupt problem.
The soundcard used to work on much older kernel versions. The only
issue I had with this chipset were general (sound, network, ...) DMA problems from 4GiB+ memory areas after I upgraded my memory, but that got fixed in newer kernel version. The soundcard uses unique IRQs:
CPU0 CPU1
43: 24 7290 PCI-MSI-edge snd_hda_intel
44: 1 60 PCI-MSI-edge snd_hda_intel
Any clues on how I can debug this?
Signature · 3 lines
Petr "Pasky" Baudis The goal of Computer Science is to build something that will last at least until we've finished building it.
Hi!
Quoted 2 lines
Quoted 1 line · Petr Baudis
I will try the then-current kernel and for-next branch then.
FYI, this issue has most likely reached a happy end. While 3.2.x
did not work properly, tonight I finally could reboot the machine with tiwai's for-next branch and cannot reproduce the issue so far!
I'm not sure if this is thanks to an unrelated change in interrupt
handling that got pulled around or something that's actually brewing in the for-next branch but hopefully it will eventually find its way to the distribution kernels. :-)
Thanks,
Petr "Pasky" Baudis