Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Jonathan Nieder]

Hi Petr,

Petr Baudis wrote[1]:

> Version: 3.1.5-1
[...]
> 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.
[...]
> This did not use to happen at least back around 2.6.32.
[...]
> 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

> (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=0x01db0000
>
> gets 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_SYNC will 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.
[...]
> [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
[...]
> bios_vendor: American Megatrends Inc.
> bios_version: 1009   
> board_vendor: ASUSTeK Computer INC.
> board_name: M2R32-MVP
> board_version: Rev 1.xx
[...]
> 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 at fbcf0000 (64-bit, non-prefetchable) [size=16K]
> 	Capabilities: <access denied>
> 	Kernel driver in use: snd_hda_intel

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Petr Baudis]

  Hi!

On Thu, Dec 29, 2011 at 12:21:05AM -0600, Jonathan Nieder wrote:
> Petr Baudis wrote[1]:
> 
> > Version: 3.1.5-1
> [...]
> > 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.
> [...]
> > This did not use to happen at least back around 2.6.32.
> [...]
> > 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.

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

-- 
				Petr "Pasky" Baudis
	The goal of Computer Science is to build something that will
	last at least until we've finished building it.

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Takashi Iwai]

At Sat, 21 Jan 2012 10:16:02 +0100,
Petr Baudis wrote:
> 
>   Hi!
> 
> On Thu, Dec 29, 2011 at 12:21:05AM -0600, Jonathan Nieder wrote:
> > Petr Baudis wrote[1]:
> > 
> > > Version: 3.1.5-1
> > [...]
> > > 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.
> > [...]
> > > This did not use to happen at least back around 2.6.32.
> > [...]
> > > 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.
> 
> 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

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

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Petr Baudis]

On Mon, Jan 23, 2012 at 10:18:24AM +0100, Takashi Iwai wrote:
> 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.

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.

-- 
				Petr "Pasky" Baudis
	The goal of Computer Science is to build something that will
	last at least until we've finished building it.

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Takashi Iwai]

At Mon, 23 Jan 2012 10:46:30 +0100,
Petr Baudis wrote:
> 
> On Mon, Jan 23, 2012 at 10:18:24AM +0100, Takashi Iwai wrote:
> > 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.
> 
> 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?

> 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

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Petr Baudis]

On Mon, Jan 23, 2012 at 10:51:43AM +0100, Takashi Iwai wrote:
> At Mon, 23 Jan 2012 10:46:30 +0100,
> Petr Baudis wrote:
> > 
> > On Mon, Jan 23, 2012 at 10:18:24AM +0100, Takashi Iwai wrote:
> > > 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.
> > 
> > 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.

> > 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?

-- 
				Petr "Pasky" Baudis
	The goal of Computer Science is to build something that will
	last at least until we've finished building it.

Re: hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x01db0000

[Petr Baudis]

  Hi!

> At Sat, 21 Jan 2012 10:16:02 +0100, Petr Baudis wrote:
> > 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