Repository navigation
[BUG]"codec #1 probe error, ret: -5" occurred when run reboot stress test. #1558
Description
Describe the bug
Occurred unexpected ipc interrupt raised when run reboot stress test.
To Reproduce
- Put "./test-reboot.sh" script in startup Application preferences.
- Run with command "./test-reboot.sh 500" , then check the logs in folder named reboot-logs.
script:
test-reboot.sh.txt
Reproduced rate
Run 500 times, only failed once.
Expected result
System boot up without error
Actual result
[ 3.964921] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[ 3.964928] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf010e0e successful
[ 3.964942] ------------[ cut here ]------------
[ 3.964948] irq 142 handler hda_dsp_interrupt_handler+0x0/0x70 [snd_sof_intel_hda_common] enabled interrupts
[ 3.964956] WARNING: CPU: 7 PID: 802 at kernel/irq/handle.c:153 __handle_irq_event_percpu+0x178/0x180
[ 3.964958] Modules linked in: snd_soc_rt711 snd_soc_rt700 snd_soc_rt715 snd_soc_rt1308_sdw regmap_sdw snd_soc_dmic snd_sof_pci snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel_init soundwire_intel soundwire_generic_allocation soundwire_cadence 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 soundwire_bus snd_soc_core snd_intel_dspcfg snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device snd_timer snd asix usbnet x86_pkg_temp_thermal soundcore intel_powerclamp processor_thermal_device intel_soc_dts_iosf mei_me intel_lpss_pci mei intel_lpss mfd_core int3403_thermal int3400_thermal int340x_thermal_zone acpi_thermal_rel efivarfs i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect xhci_pci sysimgblt fb_sys_fops xhci_hcd drm
[ 3.964985] CPU: 7 PID: 802 Comm: gvfsd-fuse Not tainted 5.4.0-rc8-sdw-validation-20191127-0-d6078f9 #rc8
[ 3.964986] Hardware name: Dell Inc. Latitude 9510/, BIOS 0.1.3 10/01/2019
[ 3.964988] RIP: 0010:__handle_irq_event_percpu+0x178/0x180
[ 3.964990] Code: e8 86 ed ff ff e9 20 ff ff ff 45 31 e4 e9 24 ff ff ff 48 8b 13 89 ee 48 c7 c7 70 1e 7c 84 c6 05 ed ca 26 01 01 e8 f8 96 fa ff <0f> 0b eb b2 0f 1f 40 00 55 53 48 89 fb 48 83 ec 10 48 8d 74 24 04
[ 3.964990] RSP: 0018:ffffa866c025cf48 EFLAGS: 00010282
[ 3.964992] RAX: 0000000000000000 RBX: ffff98e662afbf00 RCX: 0000000000000006
[ 3.964992] RDX: 0000000000000007 RSI: 0000000000000096 RDI: ffff98e6643d63d0
[ 3.964993] RBP: 000000000000008e R08: 000000000000043e R09: 0000000000000004
[ 3.964993] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
[ 3.964994] R13: ffffa866c025cf8c R14: 0000000000000000 R15: 0000000000000002
[ 3.964995] FS: 0000000000000000(0000) GS:ffff98e6643c0000(0000) knlGS:0000000000000000
[ 3.964996] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 3.964997] CR2: 00007fe6c55fc860 CR3: 000000028aede001 CR4: 00000000003606e0
[ 3.964997] Call Trace:
[ 3.964999] <IRQ>
[ 3.965001] handle_irq_event_percpu+0x2b/0x70
[ 3.965002] handle_irq_event+0x22/0x40
[ 3.965004] handle_edge_irq+0x75/0x190
[ 3.965007] do_IRQ+0x41/0xd0
[ 3.965008] common_interrupt+0xf/0xf
[ 3.965009] </IRQ>
[ 3.965011] RIP: 0010:do_syscall_64+0xf/0x120
[ 3.965012] Code: 02 00 eb b4 e8 52 fd ff ff e9 5a ff ff ff 0f 1f 00 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 f5 53 fb 65 48 8b 04 25 00 5d 01 00 <48> 8b 00 a9 c1 01 08 10 0f 85 a5 00 00 00 48 81 ff b3 01 00 00 77
[ 3.965012] RSP: 0018:ffffa866c0b8ff40 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdb
[ 3.965013] RAX: ffff98e64ac6b800 RBX: 0000000000000000 RCX: 0000000000000000
[ 3.965014] RDX: 0000000000000000 RSI: ffffa866c0b8ff58 RDI: 0000000000000009
[ 3.965014] RBP: ffffa866c0b8ff58 R08: 0000000000000000 R09: 0000000000000000
[ 3.965014] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 3.965015] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 3.965017] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 3.965017] RIP: 0033:0x7fe6c65bdf43
[ 3.965018] Code: 89 f5 41 54 41 89 d4 55 48 89 fd 53 4c 89 cb 74 4e 49 89 d9 45 89 f8 45 89 f2 44 89 e2 4c 89 ee 48 89 ef b8 09 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 65 5b 5d 41 5c 41 5d 41 5e 41 5f c3 66 2e 0f
[ 3.965019] RSP: 002b:00007ffe9c0cde38 EFLAGS: 00000206 ORIG_RAX: 0000000000000009
[ 3.965020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fe6c65bdf43
[ 3.965020] RDX: 0000000000000003 RSI: 0000000000003ae0 RDI: 00007fe6c55fd000
[ 3.965020] RBP: 00007fe6c55fd000 R08: 00000000ffffffff R09: 0000000000000000
[ 3.965021] R10: 0000000000000032 R11: 0000000000000206 R12: 0000000000000003
[ 3.965021] R13: 0000000000003ae0 R14: 0000000000000032 R15: 00000000ffffffff
[ 3.965022] ---[ end trace b037ada1d7b7cf23 ]---
[ 3.965044] sof-audio-pci 0000:00:1f.3: unexpected ipc interrupt raised!
[ 3.965046] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[ 4.043457] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[ 4.056414] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5 successful
[ 4.056912] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x140000 successful
[ 4.056914] sof-audio-pci 0000:00:1f.3: Firmware download successful, booting...
[ 4.063124] sof-audio-pci 0000:00:1f.3: ipc rx: 0x70000000: FW_READY
[ 4.063126] sof-audio-pci 0000:00:1f.3: ipc: DSP is ready 0x70000000 offset 0x81000
[ 4.063235] sof-audio-pci 0000:00:1f.3: Firmware info: version 1:1:0-d740a
[ 4.063236] sof-audio-pci 0000:00:1f.3: Firmware: ABI 3:11:0 Kernel ABI 3:11:0
[ 4.063421] sof-audio-pci 0000:00:1f.3: found ext header type 1 size 0xb8
[ 4.063453] sof-audio-pci 0000:00:1f.3: mailbox upstream 0x81000 - size 0x1000
[ 4.063454] sof-audio-pci 0000:00:1f.3: mailbox downstream 0xa0000 - size 0x2000
[ 4.063455] sof-audio-pci 0000:00:1f.3: stream region 0xc1000 - size 0x1000
[ 4.063458] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x70000000: FW_READY
[ 4.063459] sof-audio-pci 0000:00:1f.3: firmware boot complete
Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: d6078f9
FW: https://github.com/thesofproject/sof/commits/master commit: d740a3e
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode
Activity
YvonneYang2 commentedon Nov 28, 2019
It seems be similar to #1540
bardliao commentedon Nov 29, 2019
Actually,
unexpected ipc interrupt raised!can be always seen on boot up. The issue isWARNING: CPU: 7 PID: 802 at kernel/irq/handle.c:153. @YvonneYang2 Could you check it on other platforms? I suspect that is not a SDW specific issue.YvonneYang2 commentedon Dec 2, 2019
@bardliao
Tested it on other platforms, only can reproduce on CML Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode. Topic/sof-dev branch didn't reproduce the issue.
Run 1000 times, failed two times.
dmesg_failed_797.log
dmesg_failed_842.log
[-][BUG][SDW]"Unexpected ipc interrupt raised" when run reboot stress test.[/-][+][BUG][SDW]Warning of "kernel/irq/handle.c:153 __handle_irq_event_percpu+0x178/0x180" occurred when run reboot stress test.[/+]bardliao commentedon Dec 3, 2019
The WARNING about the irq is due to we use spin_unlock_irq() which will enable irq unconditionally in the check irq functions. We can fix it by using spin_lock_irqsave() and spin_unlock_irqrestore(). But it is harmless. The real problem of this issue is
which will cause sound card not created.
BTW, there are some WARNING after
sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: binding iDisp1That is due to flush_delayed_work(&rtd->delayed_work); is invoked before INIT_DELAYED_WORK(&rtd->delayed_work, close_delayed_work);
plbossart commentedon Dec 3, 2019
@bardliao with your changes we only use the spinlock in the threads, so we could use a regular spin_lock, no?
that's an HDAudio/IDIPS issue. @kv2019i FYI
Huh, that's no good. we should file this as a separate issue.
[-][BUG][SDW]Warning of "kernel/irq/handle.c:153 __handle_irq_event_percpu+0x178/0x180" occurred when run reboot stress test.[/-][+][BUG][SDW]"codec #1 probe error, ret: -5" occurred when run reboot stress test.[/+]bardliao commentedon Dec 4, 2019
@plbossart Yes, the spinlock is only called in the thread with global interrupt disabled, and they are called in sequence. So, yes, I think we can use a regular spin_lock.
YvonneYang2 commentedon Dec 4, 2019
Tested it with on integration/soundwire-latest + PR1580 with sof-pci-debug=1 and sdw_md_flags=0x01000001, reproduced rate is higher than before. Reproduced rate is 6/300.
dmesg_failed_41.log
Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: b4f9bfa+ #1580
FW: https://github.com/thesofproject/sof/commits/master commit: feb9e2b
tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode
YvonneYang2 commentedon Dec 4, 2019
Split the "WARNING after sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: binding iDisp1" to #1587
kv2019i commentedon Dec 5, 2019
@plbossart wrote:
This seems like a variant of issue #1367
Dmesg has this
[ 2.962115] sof-audio-pci 0000:00:1f.3: codec_mask = 0x6
In this case, there is only one HDA codec (idisp), so the mask should be 100b (0x4), but there's
the non-existant codec #1 so mask ends up as 110b (0x6). In case of #1367, codec#0 is also present so mask ix 0x7 in that bug.
Hmm, considering this seems to be taking longer to resolve, we may have to add a temporary workaround to gracefully handle this case, while we are finding the real rootcause.
ClarexZhou commentedon Dec 6, 2019
@kv2019i Could you provide workaround solution first?
[-][BUG][SDW]"codec #1 probe error, ret: -5" occurred when run reboot stress test.[/-][+][BUG]"codec #1 probe error, ret: -5" occurred when run reboot stress test.[/+]kv2019i commentedon Dec 9, 2019
@mengdonglin wrote:
Ack, I'm working on a patchset now. I have initial version ready, but I need a day more to run tests in different scenarios before uploading for reviewing.
mptcp: fix abba deadlock on fastopen