[ThinkPad T420] hda-intel: spurious response - audio dropping out during playback

[Chris J Arges]

I am testing on raring. To reproduce try playing a you tube video, the audio will go in and out. In addition playing back music in rhythmbox will also exhibit the same problems.
When looking at dmesg I see the following lines:
[ 1653.495497] hda-intel: spurious response 0x40:0x3, last cmd=0x30270503
[ 1653.495498] hda-intel: spurious response 0x4011:0x3, last cmd=0x30270503
[ 1653.495500] hda-intel: spurious response 0x0:0x3, last cmd=0x30270503
[ 1653.495501] hda-intel: spurious response 0x5:0x3, last cmd=0x30270503
[ 1654.591127] hda_intel: azx_get_response timeout, switching to single_cmd mode: last cmd=0x301f0500

Eventually after this the audio cuts out complete and nothing can be heard. Not sure if this is a pulseaudio bug or an intel driver bug.

ProblemType: Bug
DistroRelease: Ubuntu 13.04
Package: pulseaudio 1:2.1-0ubuntu4
ProcVersionSignature: Ubuntu 3.7.0-5.13-generic 3.7.0-rc8
Uname: Linux 3.7.0-5-generic x86_64
ApportVersion: 2.7-0ubuntu1
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC0: arges 2340 F.... pulseaudio
 /dev/snd/pcmC0D0p: arges 2340 F...m pulseaudio
Date: Tue Dec 11 09:20:33 2012
EcryptfsInUse: Yes
InstallationDate: Installed on 2012-08-17 (116 days ago)
InstallationMedia: Ubuntu 12.10 "Quantal Quetzal" - Alpha amd64 (20120807.2)
MarkForUpload: True
ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: pulseaudio
UpgradeStatus: Upgraded to raring on 2012-11-26 (14 days ago)
dmi.bios.date: 11/28/2011
dmi.bios.vendor: LENOVO
dmi.bios.version: 83ET67WW (1.37 )
dmi.board.asset.tag: Not Available
dmi.board.name: 4177CTO
dmi.board.vendor: LENOVO
dmi.board.version: Not Available
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvr83ET67WW(1.37):bd11/28/2011:svnLENOVO:pn4177CTO:pvrThinkPadT420:rvnLENOVO:rn4177CTO:rvrNotAvailable:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 4177CTO
dmi.product.version: ThinkPad T420
dmi.sys.vendor: LENOVO

[David Henningsson (diwic)]

[ 1653.495497] hda-intel: spurious response 0x40:0x3, last cmd=0x30270503

is definitely a driver bug.

Is this a regression from quantal or did you see the same behaviour in previous Ubuntu releases?

[Chris J Arges (arges)]

@diwic
This has always worked in Quantal/Precise, just after updating yesterday did I encounter this issue.

[David Henningsson (diwic)]

@Chris, okay, good.

We should first try the latest upstream code according to https://wiki.ubuntu.com/Audio/UpgradingAlsa/DKMS to see if it's been already fixed again. If so, it will be fixed with the 3.8 kernels coming to 13.04 a few weeks from now, so maybe that's okay.

If it is not fixed, or if waiting for the 3.8 kernel takes too long, we have some git bisecting ahead of us to figure this one out. Unless you know how to do this yourself, can you talk to Joseph Salisbury to help you with this?

Thanks!

[Chris J Arges (arges)]

@diwic

Ok at this point it is intermittent, I will try to figure out how to reproduce as I use this laptop. And use upstream at that point and test, then bisect if I can.

[Peter Weber (r7g-bugs)]

Here a ThinkPad t430s:

I'm using Archlinux with vanilla kernel 3.7.1 and I seem affected too. I need to suspend and resume my systemd approximately two times to receive this messages. The system will still run stable and fast, but every application which plays sound becomes coppy:

mplayer on the virtual terminal, totem in Gnome-Shell or IOQuake3
I added my dmesg as attachment.

[Raymond (superquad-vortex2)]

[ 1411.726926] PM: noirq suspend of devices complete after 63.835 msecs
[ 1411.727597] ACPI: Preparing to enter system sleep state S3
[ 1411.906853] PM: Saving platform NVS memory
[ 1411.910022] Disabling non-boot CPUs ...
[ 1411.911277] smpboot: CPU 1 is now offline
[ 1411.911719] Broke affinity for irq 44
[ 1412.014797] smpboot: CPU 2 is now offline
[ 1412.015276] Broke affinity for irq 16
[ 1412.015285] Broke affinity for irq 23
[ 1412.015286] Broke affinity for irq 40
[ 1412.118778] smpboot: CPU 3 is now offline
[ 1412.119132] Extended CMOS year: 2000
[ 1412.121261] ACPI: Low-level resume complete
[ 1412.121335] PM: Restoring platform NVS memory
[ 1412.123291] Extended CMOS year: 2000
[ 1412.123411] Enabling non-boot CPUs ...
[ 1412.123550] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 1412.134486] Disabled fast string operations
[ 1412.167081] CPU1 is up
[ 1412.167126] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 1412.178159] Disabled fast string operations
[ 1412.211072] CPU2 is up
[ 1412.211118] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 1412.222152] Disabled fast string operations
[ 1412.255069] CPU3 is up
[ 1412.257991] ACPI: Waking up from system sleep state S3
[ 1412.439091] thinkpad_acpi: EC reports that Thermal Table has changed
[ 1412.615017] i915 0000:00:02.0: power state changed by ACPI to D0
[ 1412.662952] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[ 1412.678954] ehci_hcd 0000:00:1a.0: wake-up capability disabled by ACPI
[ 1412.695278] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[ 1412.710948] ehci_hcd 0000:00:1d.0: wake-up capability disabled by ACPI
[ 1412.775082] PM: noirq resume of devices complete after 160.188 msecs
[ 1412.775146] PM: early resume of devices complete after 0.042 msecs
[ 1412.775171] i915 0000:00:02.0: setting latency timer to 64
[ 1412.775172] e1000e 0000:00:19.0: wake-up capability disabled by ACPI
[ 1412.775218] mei 0000:00:16.0: irq 41 for MSI/MSI-X
[ 1412.775256] e1000e 0000:00:19.0: irq 43 for MSI/MSI-X
[ 1412.775277] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[ 1412.775321] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[ 1412.775340] ahci 0000:00:1f.2: setting latency timer to 64
[ 1412.775359] snd_hda_intel 0000:00:1b.0: irq 45 for MSI/MSI-X
[ 1412.815566] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
[ 1413.027146] usb 1-1.3: reset full-speed USB device number 3 using ehci_hcd
[ 1413.110927] ata4: SATA link down (SStatus 0 SControl 300)
[ 1413.118937] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 1413.120655] ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 1413.120661] ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 1413.120665] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 1413.121768] ata2.00: failed to get Identify Device Data, Emask 0x1
[ 1413.123376] ata2.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[ 1413.123380] ata2.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[ 1413.123383] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[ 1413.124403] ata2.00: failed to get Identify Device Data, Emask 0x1
[ 141...

[Raymond (superquad-vortex2)]

> Here a ThinkPad t430s:

 16.048391] hda-intel: Unstable LPIB (131056 >= 8192); disabling LPIB delay counting

[Matthew Thode (prometheanfire)]

I see the same issue with vanilla sources 3.7.1 in gentoo. (and hardened sources), seems like an upstream kernel issue maybe?
I reproduced via the following method.

1. boot
2. play sound (to verify working)
3. suspend / unsuspend
4. play sound (this fails)
5. dmesg :D

T520
http://forums.gentoo.org/viewtopic-t-944996-highlight-disabling+lpib+delay+counting.html
makes it seem like disabling hdmi support for hda-intel will 'fix' it.

dmesg | grep hda
[ 1.917634] snd_hda_intel 0000:00:1b.0: irq 45 for MSI/MSI-X
[ 95.881768] snd_hda_intel 0000:00:1b.0: irq 45 for MSI/MSI-X
[ 107.942919] hda-intel: azx_get_response timeout, switching to polling mode: last cmd=0x010f0600
[ 108.941656] hda-intel: No response from codec, disabling MSI: last cmd=0x010f0600
[ 109.942365] hda_intel: azx_get_response timeout, switching to single_cmd mode: last cmd=0x010f0600
[ 109.966911] hda-intel: Unstable LPIB (56856 >= 8192); disabling LPIB delay counting

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Peter Weber (r7g-bugs)]

Well. I'm not sure if this is already fixed upstream:
http://comments.gmane.org/gmane.linux.alsa.devel/103004

Should we open a bug at bugzilla.kernel.org?

[Peter Weber (r7g-bugs)]

> Great, now I merged both fix patches to sound git tree.
> They'll be included in the next pull request.

[Peter Weber (r7g-bugs)]

I'm an idiot. This patch was for AMD based systems.

[David Henningsson (diwic)]

@peter weber, I'm not sure what you're referring to is the same bug, since the controller chips are different.

[Peter Weber (r7g-bugs)]

Your right. I just read "intel-hda" and didn't read the "AMD".

https://bugzilla.kernel.org/show_bug.cgi?id=52291

[David Henningsson (diwic)]

They're discussing similar issues upstream: Will any of the following help this issue too?

* edit /etc/modprobe.d/alsa-base.conf and insert this line
options snd-hda-intel enable_msi=0

Reboot and test. If this does not work, remove the line you added and instead add:
options snd-hda-intel power_save_controller=0

Reboot and test again. Thanks!

[Matthew Thode (prometheanfire)]

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=44728e97c35ef31d649dafbbada665e37176f5da may fix it, have not been able to verify.

also, power_save_controller=0 'fixed' it

[aaronpoweruser (aaronpoweruser)]

Confirmed on a hp dv6 with an i7 12.10 linux 3.7.1 and gnome 3.6

[Peter Weber (r7g-bugs)]

I'm not able (half hour of susped/resume cycles) this bug with Kernel 3.7.2.
Anyone else?

[koma (koen-koma)]

[ 4.530969] current rate 47872 is different from the runtime rate 48000
[ 4.532567] current rate 47872 is different from the runtime rate 48000
[ 4.542074] current rate 47872 is different from the runtime rate 48000
[ 4.543663] current rate 47872 is different from the runtime rate 48000
[ 6.988084] alx 0000:03:00.0 eth0: NIC Up: 1 Gbps Full
[ 7.556984] alx 0000:03:00.0 eth0: Link Down
[ 9.742737] alx 0000:03:00.0 eth0: NIC Up: 1 Gbps Full
[ 12.853590] current rate 47872 is different from the runtime rate 48000
[ 12.855306] current rate 47872 is different from the runtime rate 48000
[ 12.865532] current rate 47872 is different from the runtime rate 48000
[ 12.867129] current rate 47872 is different from the runtime rate 48000
[ 21.292335] current rate 47872 is different from the runtime rate 48000
[ 21.293919] current rate 47872 is different from the runtime rate 48000
[ 31.830409] audit_printk_skb: 108 callbacks suppressed
[ 31.830411] type=1400 audit(1429190327.831:47): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=2503 comm="apparmor_parser"
[ 31.830414] type=1400 audit(1429190327.831:48): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2503 comm="apparmor_parser"
[ 31.830678] type=1400 audit(1429190327.831:49): apparmor="STATUS" operation="profile_replace" profile="unconfined" name="/usr/sbin/cupsd" pid=2503 comm="apparmor_parser"
[ 598.180586] current rate 47872 is different from the runtime rate 48000
[ 598.182285] current rate 47872 is different from the runtime rate 48000
[ 1192.928332] hda-intel: IRQ timing workaround is activated for card #0. Suggest a bigger bdl_pos_adj.
[ 1422.073507] hda-intel 0000:00:1b.0: Unstable LPIB (32768 >= 2048); disabling LPIB delay counting
[ 5273.853061] current rate 47872 is different from the runtime rate 48000
[ 5273.854661] current rate 47872 is different from the runtime rate 48000
[ 5289.156834] current rate 47872 is different from the runtime rate 48000
[ 5289.158392] current rate 47872 is different from the runtime rate 48000

[Marcus Tomlinson (marcustomlinson)]

This release of Ubuntu is no longer receiving maintenance updates. If this is still an issue on a maintained version of Ubuntu please let us know.

[Marcus Tomlinson (marcustomlinson)]

This issue has sat incomplete for more than 60 days now. I'm going to close it as invalid. Please feel free re-open if this is still an issue for you. Thank you.