[alsa-devel] CPU hook snd_hda_intel

Tue Dec 10 16:10:37 CET 2019

Hi Takashi,

Am Di den 10. Dez 2019 um 15:43 schrieb Takashi Iwai:
> > There is also a issue with a swapper thread in ath9k code but the one
> > with the biggest CPU hook is still alsa.
> 
> Do you see the relevant kernel messages, e.g. switch to polling mode?

Nope.

Here is the relevant logs starting from undocking event up to the sleep
that I mentioned fixing the issue:
   Dec 10 15:19:12 chua kernel: [14611.133847] ACPI: \_SB_.GDCK: undocking
   Dec 10 15:19:12 chua kernel: [14611.137923] usb 1-4: USB disconnect, device number 5
   Dec 10 15:19:13 chua kernel: [14611.360780] thinkpad_acpi: woke up due to a hot-unplug request...
   Dec 10 15:19:13 chua kernel: [14611.361034] thinkpad_acpi: undocked
   Dec 10 15:19:13 chua kernel: [14611.361509] ACPI: \_SB_.GDCK: undocking
   Dec 10 15:19:16 chua kernel: [14614.688138] Monitor-Mwait will be used to enter C-3 state
   Dec 10 15:19:16 chua kernel: [14614.909277] sd 0:0:0:0: [sda] Synchronizing SCSI cache
   Dec 10 15:19:16 chua kernel: [14614.910426] sd 0:0:0:0: [sda] Stopping disk
   Dec 10 15:19:17 chua kernel: [14615.279585] e1000e: eth0 NIC Link is Down
   Dec 10 15:19:17 chua kernel: [14615.995311] sd 0:0:0:0: [sda] Starting disk
   Dec 10 15:19:18 chua kernel: [14616.840213] BTRFS warning (device dm-3): excessive commit interval 600
   Dec 10 15:19:18 chua kernel: [14616.840217] BTRFS info (device dm-3): disk space caching is enabled
   [more of the last two lines]
   Dec 10 15:19:19 chua kernel: [14617.856624] e1000e: eth0 NIC Link is Down
   Dec 10 15:19:26 chua kernel: [14624.416815] wlan0: authenticate with 1a:e8:29:62:36:fc
   Dec 10 15:19:26 chua kernel: [14624.422409] wlan0: send auth to 1a:e8:29:62:36:fc (try 1/3)
   Dec 10 15:19:26 chua kernel: [14624.450142] wlan0: authenticated
   Dec 10 15:19:26 chua kernel: [14624.450480] wlan0: associate with 1a:e8:29:62:36:fc (try 1/3)
   Dec 10 15:19:26 chua kernel: [14624.455014] wlan0: RX AssocResp from 1a:e8:29:62:36:fc (capab=0x411 status=0 aid=3)
   Dec 10 15:19:26 chua kernel: [14624.455363] wlan0: associated
   Dec 10 15:19:26 chua kernel: [14624.460321] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
   Dec 10 15:19:42 chua kernel: [14640.895731] e1000e: eth0 NIC Link is Down
   Dec 10 15:19:52 chua kernel: [14650.415684] e1000e: eth0 NIC Link is Down
   Dec 10 15:19:55 chua kernel: [14653.332765] wlan0: authenticate with 1a:e8:29:62:36:fc
   Dec 10 15:19:55 chua kernel: [14653.337337] wlan0: send auth to 1a:e8:29:62:36:fc (try 1/3)
   Dec 10 15:19:55 chua kernel: [14653.397026] wlan0: send auth to 1a:e8:29:62:36:fc (try 2/3)
   Dec 10 15:19:55 chua kernel: [14653.463283] wlan0: send auth to 1a:e8:29:62:36:fc (try 3/3)
   Dec 10 15:19:55 chua kernel: [14653.522603] wlan0: authentication with 1a:e8:29:62:36:fc timed out
   Dec 10 15:20:34 chua kernel: [14692.783662] e1000e: eth0 NIC Link is Down
   Dec 10 15:23:36 chua kernel: [14874.223723] perf: interrupt took too long (2597 > 2500), lowering kernel.perf_event_max_sample_rate to 77000
   Dec 10 15:23:36 chua kernel: [14874.227937] perf: interrupt took too long (3335 > 3246), lowering kernel.perf_event_max_sample_rate to 59000
   Dec 10 15:23:36 chua kernel: [14874.232928] perf: interrupt took too long (4169 > 4168), lowering kernel.perf_event_max_sample_rate to 47000
   Dec 10 15:23:36 chua kernel: [14874.241582] perf: interrupt took too long (5233 > 5211), lowering kernel.perf_event_max_sample_rate to 38000
   Dec 10 15:23:36 chua kernel: [14874.252231] perf: interrupt took too long (6548 > 6541), lowering kernel.perf_event_max_sample_rate to 30000
   Dec 10 15:23:36 chua kernel: [14874.267034] perf: interrupt took too long (8211 > 8185), lowering kernel.perf_event_max_sample_rate to 24000
   Dec 10 15:23:36 chua kernel: [14874.295426] perf: interrupt took too long (10276 > 10263), lowering kernel.perf_event_max_sample_rate to 19000
   Dec 10 15:23:37 chua kernel: [14875.392080] perf: interrupt took too long (12851 > 12845), lowering kernel.perf_event_max_sample_rate to 15000
   Dec 10 15:24:09 chua kernel: [14907.880874] e1000e: eth0 NIC Link is Down
   Dec 10 15:24:12 chua kernel: [14910.754897] wlan0: authenticate with 1a:e8:29:e1:1c:4b
   Dec 10 15:24:12 chua kernel: [14910.759170] wlan0: send auth to 1a:e8:29:e1:1c:4b (try 1/3)
   Dec 10 15:24:12 chua kernel: [14910.764932] wlan0: authenticated
   Dec 10 15:24:12 chua kernel: [14910.765477] wlan0: associate with 1a:e8:29:e1:1c:4b (try 1/3)
   Dec 10 15:24:12 chua kernel: [14910.778257] wlan0: RX AssocResp from 1a:e8:29:e1:1c:4b (capab=0x431 status=0 aid=8)
   Dec 10 15:24:12 chua kernel: [14910.778651] wlan0: associated
   Dec 10 15:24:12 chua kernel: [14910.785585] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
   Dec 10 15:33:47 chua kernel: [15485.695970] wlan0: deauthenticating from 1a:e8:29:e1:1c:4b by local choice (Reason: 3=DEAUTH_LEAVING)
   Dec 10 15:33:48 chua kernel: [15486.359726] e1000e: eth0 NIC Link is Down
   Dec 10 15:33:49 chua kernel: [15487.208769] e1000e: eth0 NIC Link is Down
   Dec 10 15:33:49 chua kernel: [15487.717376] ath9k: ath9k: Driver unloaded
   Dec 10 15:33:50 chua kernel: [15488.357624] PM: suspend entry (deep)
   Dec 10 15:33:55 chua kernel: [15488.381517] Filesystems sync: 0.023 seconds
   Dec 10 15:33:55 chua kernel: [15488.381942] Freezing user space processes ... (elapsed 0.001 seconds) done.
   Dec 10 15:33:55 chua kernel: [15488.383328] OOM killer disabled.
   Dec 10 15:33:55 chua kernel: [15488.383329] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
   Dec 10 15:33:55 chua kernel: [15488.384424] printk: Suspending console(s) (use no_console_suspend to debug)
   Dec 10 15:33:55 chua kernel: [15488.386563] sd 0:0:0:0: [sda] Synchronizing SCSI cache
   Dec 10 15:33:55 chua kernel: [15488.387436] sd 0:0:0:0: [sda] Stopping disk
   Dec 10 15:33:55 chua kernel: [15488.407871] serial 00:05: disabled
   Dec 10 15:33:55 chua kernel: [15488.409065] e1000e: EEE TX LPI TIMER: 00000000
   Dec 10 15:33:55 chua kernel: [15488.497441] snd_hdac_bus_update_rirb: 58 callbacks suppressed
   Dec 10 15:33:55 chua kernel: [15488.497449] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497453] snd_hda_intel 0000:00:1b.0: spurious response 0x7fffffff:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497457] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497461] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497464] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497468] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497471] snd_hda_intel 0000:00:1b.0: spurious response 0x7fffffff:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497475] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497478] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.497481] snd_hda_intel 0000:00:1b.0: spurious response 0x0:0x0, last cmd=0x11f0900
   Dec 10 15:33:55 chua kernel: [15488.554013] ACPI: EC: interrupt blocked
   Dec 10 15:33:55 chua kernel: [15488.566977] ACPI: Preparing to enter system sleep state S3
   Dec 10 15:33:55 chua kernel: [15488.583067] ACPI: EC: event blocked
   Dec 10 15:33:55 chua kernel: [15488.583069] ACPI: EC: EC stopped
   Dec 10 15:33:55 chua kernel: [15488.583070] PM: Saving platform NVS memory
   Dec 10 15:33:55 chua kernel: [15488.583426] Disabling non-boot CPUs ...
   Dec 10 15:33:55 chua kernel: [15488.584808] smpboot: CPU 1 is now offline

> > Let me add that this time I encountered the issue after taking the
> > laptop from the docking station.
> 
> ... this can be the cause: the hardware doesn't react to the pin jack
> sense request for the dock that isn't present any longer.
> Or something goes wrong here, repeating, etc.

I think, it might have to do with that as I often use the dock.

However, I think, I even seen the problem after I did a fresh boot far
away from the dock.

> > After sending it to sleep and waking it up again, the problem is gone
> > (as it often can be solved).
> 
> So the problem is very likely some flaky hardware response.

Anything you think can be done against that?

Regards
   Klaus
-- 
Klaus Ethgen                                       http://www.ethgen.ch/
pub  4096R/4E20AF1C 2011-05-16            Klaus Ethgen <Klaus at Ethgen.ch>
Fingerprint: 85D4 CA42 952C 949B 1753  62B3 79D0 B06F 4E20 AF1C
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 688 bytes
Desc: not available
URL: <http://mailman.alsa-project.org/pipermail/alsa-devel/attachments/20191210/f05ab357/attachment.sig>