Repository navigation
[WHL/CML] kernel warning on failed hw_params #938
Description
This bug looks similar to the one logged for Broadwell (#932) , so likely we have a systematic flaw at the kernel level
On a WHL device, I am able to load the firmware and topology. When trying to open a DMIC capture device, I have a timeout error and a dmesg warning telling me that the kernel error handling is not quite right.
root@plb-Swift-SF314-55:~# arecord -l
**** List of CAPTURE Hardware Devices ****
card 0: sofsklhdacard [sof-skl_hda_card], device 0: HDA Analog (*) []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofsklhdacard [sof-skl_hda_card], device 1: HDA Digital (*) []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofsklhdacard [sof-skl_hda_card], device 6: DMIC32 (*) []
Subdevices: 1/1
Subdevice #0: subdevice #0
card 0: sofsklhdacard [sof-skl_hda_card], device 7: DMIC16 (*) []
Subdevices: 1/1
Subdevice #0: subdevice #0
I have no idea what DMIC32 is supposed to be, this makes no sense but regardless when using it I get kernel warning.
root@plb-Swift-SF314-55:~# arecord -Dhw:0,6 -c2 -r48000 -fS24_LE
Recording WAVE 'stdin' : Signed 24 bit Little Endian, Rate 48000 Hz, Stereo
arecord: set_params:1363: Unable to install hw params:
ACCESS: RW_INTERLEAVED
FORMAT: S24_LE
SUBFORMAT: STD
SAMPLE_BITS: 32
FRAME_BITS: 64
CHANNELS: 2
RATE: 48000
PERIOD_TIME: 42500
PERIOD_SIZE: 2040
PERIOD_BYTES: 16320
PERIODS: (4 5)
BUFFER_TIME: 170500
BUFFER_SIZE: 8184
BUFFER_BYTES: 65472
TICK_TIME: 0
and dmesg looks quite bad, with a set of IPC errors leading to a kernel trace.
[ 62.369217] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 62.369774] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[ 62.369789] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010e0e successful
[ 62.369881] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[ 62.443415] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[ 65.443661] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 timedout
[ 65.443677] sof-audio-pci 0000:00:1f.3: error: load fw failed ret: -110
[ 65.443731] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
[ 65.443740] sof-audio-pci 0000:00:1f.3: error: status = 0x00000000 panic = 0x00000000
[ 65.443748] sof-audio-pci 0000:00:1f.3: unknown ROM status value 05000001
[ 65.443755] sof-audio-pci 0000:00:1f.3: error: failed to reset DSP
[ 65.443761] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
[ 65.443788] sof-audio-pci 0000:00:1f.3: pcm: open stream 6 dir 1
[ 65.443793] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 65.443797] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 65.443800] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 65.444428] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 6 dir 1
[ 65.444436] sof-audio-pci 0000:00:1f.3: generating page table for 0000000049e556b9 size 0xffc0 pages 16
[ 65.444476] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 65.444480] sof-audio-pci 0000:00:1f.3: periods:4
[ 65.444507] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 65.444526] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 65.749045] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60010000 size 108
[ 65.749070] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 65.749078] sof-audio-pci 0000:00:1f.3: error: status = 0x001c003c panic = 0x00000003
[ 65.749086] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 65.749096] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040000 mask 0x00000000
[ 65.749102] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 1
[ 65.749108] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -110
[ 65.749116] DMIC32: ASoC: hw_params FE failed -110
[ 65.749133] sof-audio-pci 0000:00:1f.3: pcm: free stream 6 dir 1
[ 65.749140] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 66.052757] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 66.052783] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 66.052791] sof-audio-pci 0000:00:1f.3: error: status = 0x001c003c panic = 0x00000003
[ 66.052800] sof-audio-pci 0000:00:1f.3: unknown ROM status value 01009701
[ 66.052810] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00040000 mask 0x00000000
[ 66.052838] WARNING: CPU: 1 PID: 2583 at /data/pbossart/ktest/sof-dev/kernel/workqueue.c:3030 __flush_work+0x19f/0x1b0
[ 66.052840] Modules linked in: snd_soc_skl_hda_dsp snd_soc_hdac_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_soc_dmic sof_pci_dev snd_sof_intel_hda_common snd_soc_hdac_hda snd_sof_intel_hda snd_sof_intel_byt snd_soc_acpi_intel_match snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_acpi snd_hda_ext_core iwlmvm snd_soc_core snd_hda_codec snd_hwdep snd_hda_core snd_pcm intel_lpss_pci mei_me iwlwifi x86_pkg_temp_thermal intel_powerclamp intel_lpss intel_pch_thermal mei mfd_core efivarfs xhci_pci xhci_hcd
[ 66.052879] CPU: 1 PID: 2583 Comm: arecord Not tainted 5.1.0-test+ #78
[ 66.052882] Hardware name: Acer Swift SF314-55/MILLER_WL, BIOS V1.05 10/03/2018
[ 66.052891] RIP: 0010:__flush_work+0x19f/0x1b0
[ 66.052895] Code: ff 8b 4d 00 48 8b 55 08 83 e1 08 48 0f ba 6d 00 03 80 c9 f0 eb c6 41 c6 45 00 00 fb 31 c0 e9 e1 fe ff ff 0f 0b e9 da fe ff ff <0f> 0b 31 c0 e9 d1 fe ff ff e8 33 2d fe ff 0f 1f 00 31 f6 e9 49 fe
[ 66.052898] RSP: 0018:ffffb2b5820a7bd0 EFLAGS: 00010246
[ 66.052903] RAX: 0000000000000000 RBX: ffff90476057a4d8 RCX: 0000000000000000
[ 66.052905] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff90476057a4d8
[ 66.052908] RBP: ffff90476057a4d8 R08: 0000000000000a8e R09: 000000000000006e
[ 66.052910] R10: 00000000000004f3 R11: ffffb2b5820a7958 R12: 0000000000000000
[ 66.052912] R13: ffffb2b5820a7c68 R14: ffffffff97c7c890 R15: 0000000000000001
[ 66.052916] FS: 00007f22c4c86740(0000) GS:ffff904765a40000(0000) knlGS:0000000000000000
[ 66.052919] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 66.052922] CR2: 00007ffd548cff88 CR3: 000000025394e003 CR4: 00000000003606e0
[ 66.052925] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 66.052927] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 66.052929] Call Trace:
[ 66.052946] ? sof_ipc_tx_message_unlocked+0x2c0/0x2d0 [snd_sof]
[ 66.052954] __cancel_work_timer+0x11f/0x1a0
[ 66.052963] ? sof_ipc_tx_message+0x61/0x80 [snd_sof]
[ 66.052971] sof_pcm_hw_free+0x158/0x170 [snd_sof]
[ 66.052987] ? soc_pcm_hw_free+0x1c3/0x1d0 [snd_soc_core]
[ 66.053000] soc_pcm_components_hw_free+0x5c/0x80 [snd_soc_core]
[ 66.053011] soc_pcm_hw_free+0x121/0x1d0 [snd_soc_core]
[ 66.053024] dpcm_fe_dai_hw_free+0x73/0x100 [snd_soc_core]
[ 66.053036] snd_pcm_hw_params+0x12d/0x5d0 [snd_pcm]
[ 66.053046] ? _cond_resched+0x10/0x40
[ 66.053052] ? __kmalloc_track_caller+0x130/0x1b0
[ 66.053062] snd_pcm_common_ioctl+0x19e/0xc80 [snd_pcm]
[ 66.053072] snd_pcm_ioctl+0x25/0x30 [snd_pcm]
[ 66.053079] do_vfs_ioctl+0x9f/0x620
[ 66.053086] ksys_ioctl+0x6b/0x80
[ 66.053093] __x64_sys_ioctl+0x11/0x20
[ 66.053098] do_syscall_64+0x43/0xf0
[ 66.053108] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 66.053113] RIP: 0033:0x7f22c40715d7
[ 66.053118] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
[ 66.053120] RSP: 002b:00007ffd548d00f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 66.053125] RAX: ffffffffffffffda RBX: 000055b6876adc30 RCX: 00007f22c40715d7
[ 66.053128] RDX: 00007ffd548d02a0 RSI: 00000000c2604111 RDI: 0000000000000004
[ 66.053130] RBP: 00007ffd548d02a0 R08: 0000000000000000 R09: 0000000000000000
[ 66.053133] R10: 0000000000000004 R11: 0000000000000246 R12: 000055b6876adca0
[ 66.053135] R13: 00007ffd548d0124 R14: 0000000000000000 R15: 7ffffffffffffffe
[ 66.053140] ---[ end trace 0600e20faad30521 ]---
@lyakh we probably need your help to figure out what happens here.
Activity
plbossart commentedon May 13, 2019
forgot to mention
kernel: 7271e69
firmware: e4a9f86 (w/ production key)
topology: sof-hda-generic.tplg
ClarexZhou commentedon May 14, 2019
ipc timed out issue occurred on CML laptop during modules reload stress test.
Environment
Rander UCM https://github.com/RanderWang/intel-UCM
Kernel repo：3cfd789 https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: 3f1b929 https://github.com/thesofproject/sof/commits/master |
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
boot_fail.log
[-][WHL] kernel warning on failed hw_params[/-][+][WHL/CML] kernel warning on failed hw_params[/+]tlauda commentedon May 14, 2019
@plbossart Logs indicate that the second boot of FW after previous ctx save has failed:
Status
0x5000001points to the ROM still waiting for the FW to be loaded using Host DMA. Maybe there is the difference between the DMA id sent to the ROM (boot config msg from kernel) and the used one.@ClarexZhou How did you figure it's the same issue? Please be smart when reporting the problems. Your dmesg log isn't starting from beginning, so I have no idea, what has started this set of ipc timeouts. Also FW log is missing.
ClarexZhou commentedon May 14, 2019
@tlauda I though might same for checking the dmesg and find same ipc timed out error. And sof-logger catching failed during auto test last night. Will keep monitor and upload FW log once error occurred again.
mengdonglin commentedon May 15, 2019
@plbossart Please check if Rajani's PR can fix this issue?
#895
thesofproject/sof#1354
lyakh commentedon May 17, 2019
Are these two problems? (1) "fw failed to load" and (2) WARNING in __flush_work? The latter is also addressed in #932 , the former in #940 ? Better handle them separately, I think.
ranj063 commentedon May 20, 2019
@plbossart it looks like my PR 895 and FW PR 1354 fixes this issue as well. I am able to record from device 6 with these.
lgirdwood commentedon May 23, 2019
@ranj063 @mengdonglin can we close if fixed ?
wenqingfu commentedon May 23, 2019
@plbossart as the issue reporter, can you still reproduce it with latest 895/1354 from? if not, we can close
plbossart commentedon May 24, 2019
Closing in the kernel warning disappeared, but the timeout issue remains.
wenqingfu commentedon May 27, 2019
"IPC timed out" issue moves on to track in #969