Bug 208829
Summary: | Multiple "spurious response" errors on resume from snd_hda_intel for NVIDIA | ||
---|---|---|---|
Product: | Drivers | Reporter: | Artem S. Tashkinov (aros) |
Component: | Sound(ALSA) | Assignee: | Jaroslav Kysela (perex) |
Status: | RESOLVED WILL_NOT_FIX | ||
Severity: | normal | CC: | belegdol, michelhanzen, ne-vlezay80, saurabh.0262, szotsaki, this.platypus, tiwai, username.murphy |
Priority: | P1 | ||
Hardware: | x86-64 | ||
OS: | Linux | ||
URL: | https://forums.developer.nvidia.com/t/nvidia-hdmi-audio-errors-after-resume-snd-hda-intel-spurious-response-last-cmd/149003 | ||
Kernel Version: | 5.7.10, git | Subsystem: | |
Regression: | No | Bisected commit-id: | |
Bug Depends on: | 204199 | ||
Bug Blocks: | |||
Attachments: | Silence snd_hda_intel spurious response last cmd messages |
Description
Artem S. Tashkinov
2020-08-06 11:51:24 UTC
Is there a way to at least silence these messages? I'm looking at void snd_hdac_bus_update_rirb(struct hdac_bus *bus) and it looks like there's no way to silence it. It would be great if you made it possible to silence it or to limit it to a single message, e.g. snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: further spurious response messages will not be omitted A similar bug was filed more than a year ago, see bug 202423. Not a single reply from ALSA developers. Is there any information I can provide so that you fixed it? It's really annoying. Then there's bug 208487 which mentions a similar device: NVIDIA Corporation TU106 High Definition Audio Controller (rev a1) After resuming there's an unusual message in dmesg: On boot: snd_hda_intel 0000:07:00.1: Disabling MSI snd_hda_intel 0000:09:00.4: enabling device (0000 -> 0002) snd_hda_codec_realtek hdaudioC1D0: ALCS1200A: SKU not ready 0x00000000 snd_hda_codec_realtek hdaudioC1D0: autoconfig for ALCS1200A: line_outs=3 (0x14/0x15/0x16/0x0/0x0) type:line snd_hda_codec_realtek hdaudioC1D0: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0) snd_hda_codec_realtek hdaudioC1D0: hp_outs=1 (0x1b/0x0/0x0/0x0/0x0) snd_hda_codec_realtek hdaudioC1D0: mono: mono_out=0x0 snd_hda_codec_realtek hdaudioC1D0: dig-out=0x1e/0x0 snd_hda_codec_realtek hdaudioC1D0: inputs: snd_hda_codec_realtek hdaudioC1D0: Front Mic=0x19 snd_hda_codec_realtek hdaudioC1D0: Rear Mic=0x18 snd_hda_codec_realtek hdaudioC1D0: Line=0x1a After resuming: snd_hda_intel 0000:07:00.1: azx_get_response timeout, switching to polling mode: last cmd=0x001f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0xc0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x84:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: spurious response 0x1:0x0, last cmd=0x1f000a snd_hda_intel 0000:07:00.1: azx_get_response timeout, switching to single_cmd mode: last cmd=0x005f0900 snd_hda_codec_hdmi hdaudioC0D0: HDMI: invalid ELD buf size -1 snd_hda_codec_hdmi hdaudioC0D0: HDMI: invalid ELD buf size -1 snd_hda_codec_hdmi hdaudioC0D0: HDMI: invalid ELD buf size -1 snd_hdac_bus_update_rirb: 500 callbacks suppressed snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0700 snd_hda_intel 0000:07:00.1: spurious response 0x40:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473501 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473502 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hdac_bus_update_rirb: 203 callbacks suppressed snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0700 snd_hda_intel 0000:07:00.1: spurious response 0x40:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473501 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473502 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hdac_bus_update_rirb: 65 callbacks suppressed snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473501 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473502 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hdac_bus_update_rirb: 301 callbacks suppressed snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x870e00 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0700 snd_hda_intel 0000:07:00.1: spurious response 0x40:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x820000 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473500 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473501 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x4f0015 snd_hda_intel 0000:07:00.1: spurious response 0x3:0x0, last cmd=0x473502 snd_hda_intel 0000:07:00.1: spurious response 0x0:0x0, last cmd=0x470700 Related issues: https://forums.developer.nvidia.com/t/hdmi-audio-changes-the-eld-pin-node-after-resume-from-suspend-mode/78190 The affected GPUs so far: NVIDIA GeForce GTX 1050, NVIDIA GeForce RTX 2080, NVIDIA GeForce RTX 2070, NVIDIA GeForce GTX 1660 Ti *** Bug 208487 has been marked as a duplicate of this bug. *** *** Bug 202423 has been marked as a duplicate of this bug. *** A much older gpu is also affected - Geforce 680M. A possible workaround is mentioned here: https://bugzilla.kernel.org/show_bug.cgi?id=204199#c14 however I'm not concerned with the switch to polling mode, I'm annoyed by a large number of never-ending error messages. Created attachment 292171 [details]
Silence snd_hda_intel spurious response last cmd messages
Totally untested
OK, the patch works for me, great. No more dmesg spam. I could have made it a snd_hda_module option but I see no reason to see thousands of these messages in the first place. It's a HDMI device in Nvidia GPU, and it means that the GPU doens't respond to the audio verbs, so basically a bug in the graphics side. Are you using Nvidia graphics driver? If it were nouveau, it should have been done better in the audio component and the power management is linked tightly. (In reply to Takashi Iwai from comment #13) > It's a HDMI device in Nvidia GPU, and it means that the GPU doens't respond > to the audio verbs, so basically a bug in the graphics side. Somehow it's only happening after resume and it doesn't affect audio output at all, so the hundreds of error messages serve no purpose. > > Are you using Nvidia graphics driver? If it were nouveau, it should have > been done better in the audio component and the power management is linked > tightly. Yes, I am, in fact I indicated it right away, comment #0 07:00.1 Audio device: NVIDIA Corporation TU116 High Definition Audio Controller (rev a1) Since NVIDIA doesn't want to address the bug (it's been known for a year and a half now) it would be great if kernel maintainers could at least somewhat alleviate it. Basically it's a problem in the resume procedure where Nvidia graphics doesn't resume quickly enough before the audio gets resumed -- that's the wild guess, but who knows. It's Nvidia binary-only stuff. You might try to change codec->relaxed_resume = 0; in generic_hdmi_free() in patch_hdmi.c to codec->relaxed_resume = 1; This would suppress the forced resume when the device has been already runtime-suspended beforehand. (In reply to Takashi Iwai from comment #15) > Basically it's a problem in the resume procedure where Nvidia graphics > doesn't resume quickly enough before the audio gets resumed -- that's the > wild guess, but who knows. It's Nvidia binary-only stuff. I'm not sure about that - these messages keep on coming _infinitely_ after resume. It surely looks like it's because PulseAudio is poking and probing the card regularly. For instance, I've noticed that unlocking the PC generates a storm of these messages. Again it would be nice to silence them because I doubt a single user in the world can use them and they are mostly meant for kernel audio developers and one error message would be enough to realize that something doesn't work correctly. TLDR It would be nice if these messages were silenced unless kernel/ALSA debugging is turned on. > > You might try to change > codec->relaxed_resume = 0; > in generic_hdmi_free() in patch_hdmi.c to > codec->relaxed_resume = 1; > > This would suppress the forced resume when the device has been already > runtime-suspended beforehand. I'm not sure that'll help - see above. Well, look at the messages you posted initially: [ 9426.756113] snd_hda_intel 0000:07:00.1: azx_get_response timeout, switching to polling mode: last cmd=0x001f000a This starts showing the spurious response. This already indicates something broken. And later on, it reaches to the state: [ 9427.760124] snd_hda_intel 0000:07:00.1: azx_get_response timeout, switching to single_cmd mode: last cmd=0x005f0900 and this means that the communication with the codec is completely broken, hence it switched to the emergency mode. After this point, the codec shouldn't return anything via the interrupt, but it still keeps doing that, and this unexpected behavior appears as the flood of response error messages. That is, the very cause is the communication error at the resume, and then the chip continues behaving weirdly after that, even if the HD-audio controller tries to communicate in the single command mode. And *why* it happens: no one knows, it's Nvidia voodoo box, hence nothing but guesses. So I asked you to try that. You can guess, but that's all about guess. For suppressing the spurious error messages after the single cmd mode switch, the change below might help. But this doesn't solve the primary problem at all, of course. --- a/sound/pci/hda/hda_controller.c +++ b/sound/pci/hda/hda_controller.c @@ -1122,7 +1122,7 @@ irqreturn_t azx_interrupt(int irq, void *dev_id) */ azx_writeb(chip, RIRBSTS, RIRB_INT_MASK); active = true; - if (status & RIRB_INT_RESPONSE) { + if (!chip->single_cmd && (status & RIRB_INT_RESPONSE)) { if (chip->driver_caps & AZX_DCAPS_CTX_WORKAROUND) udelay(80); snd_hdac_bus_update_rirb(bus); Ho ho ho -- Merry Christmas I too am seeing these messages when various terminal sessons start to go into "lock-down". The resulting malfunction is to lock-out TERM sessions under my X-Windows session. Strangely, using CTRL/ALT/F1 (console) and resuming vis CTRL/ALT/F7on an Ubuntu system give me some "better" performance on the terminal ... On the coonsole and checked htop, etc, and every thing looks "OK" apart from teh dmes output showing likes like... snd_hda_intel 0000:07:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 ... What I'd like is to find a way to identify these HEX values. For instance, what is/are ... 1. cmd=0x1f0500 2. snd_intel => 0000:07:00.1 * I presume this is a message kind??? 3. response; "0000:07:00.1" * What is that string? What service(s) usees that IPv6 address? * Ought the miscreant responsible for publishing such "stories" as-if they were .. could be... fact-s / plausibilities 4. For me it looks solved with kernel 5.9 kernel 5.4.0-58: Dec 29 13:03:33 michel-System-Test kernel: [ 49.837340] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837342] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837343] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837344] snd_hda_intel 0000:0b:00.1: spurious response 0x4011:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837345] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837346] snd_hda_intel 0000:0b:00.1: spurious response 0x4015:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837347] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837348] snd_hda_intel 0000:0b:00.1: spurious response 0x4017:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837349] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x6f0900 Dec 29 13:03:33 michel-System-Test kernel: [ 49.837350] snd_hda_intel 0000:0b:00.1: spurious response 0x4011:0x0, last cmd=0x6f0900 kernel 5.8.0-33: Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709281] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0xa70e00 Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709323] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0xa70e00 Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709394] snd_hda_intel 0000:0b:00.1: spurious response 0x3:0x0, last cmd=0x473500 Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709435] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x4f0700 Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709477] snd_hda_intel 0000:0b:00.1: spurious response 0x40:0x0, last cmd=0x470700 Dec 27 17:26:26 michel-System-Test kernel: [ 7340.709519] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x470700 Dec 27 17:26:28 michel-System-Test kernel: [ 7341.898578] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0xa20000 Dec 27 17:26:28 michel-System-Test kernel: [ 7341.898586] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0xa20000 Dec 27 17:26:28 michel-System-Test kernel: [ 7341.917887] snd_hda_intel 0000:0b:00.1: spurious response 0x0:0x0, last cmd=0x1f0500 Dec 27 17:26:28 michel-System-Test kernel: [ 7341.917913] snd_hda_intel 0000:0b:00.1: spurious response 0x233:0x0, last cmd=0x1f0500 kernel 5.9.16-050916: no "/var/log/kern.log" messages Happy New Year 2021! It is still happening with 5.10.12. However, according to NVIDIA, they are working on a fix (as of 2021-02-08): https://forums.developer.nvidia.com/t/nvidia-hdmi-audio-errors-after-resume-snd-hda-intel-spurious-response-last-cmd/149003/12 This issue goes back to 2009. End User setup issues are the hardest to fix. resolution requires reading. * When you run lspci and then a different backended hardware identification utility, are there differing naming anomolies.??? What is the exact hardware spec'd? as per Manufacturer whitepaper.? # After every install, kernel,firmware,hardware, driver change or just because ..biannually; * I run update-pciids with the latest pci.ids.(and the rest) So the hardware is identified correctly. * # I then check off the "indentified" HW against the HW actual. # Is the correct hardware audio codec pinned on the mainboard and or in the bios? Can the "driver be incorrectly chosen by the system codec?" # What about the correct dma mask/ buff setup.? # Is nvidia choking(64Mb or Higher) and the kernel is defaulting to intel?? # * I run fwupd and the relevent modprobe / dkms if needed. Is the issue that these systems are not being installed and set up. # "The cost of Open Source Free Software is the End User is free to finish the integration" # https://www.kernel.org/doc/html/latest/PCI/index.html # https://www.kernel.org/doc/html/latest/sound/hd-audio/models.html # https://help.ubuntu.com/community/SoundTroubleshootingGuide#Ae_.28.28Make_NVIDIA_HDMI_Audio_work.29 My systems have been running by the book ever since I started reading it. Hope this helps someone and for the others...flame away. NVIDIA has solved the issue themselves in the latest drivers but it may still affect older drivers which haven't been updated to include the fix. Can anyone running older NVIDIA drivers and a sufficiently recent kernel, 5.14.14, confirm that this is still an issue? NVIDIA has fixed this in their driver. |