Repository navigation
[BUG] DSP panic when stopping arecord while aplay is running #2233
Description
Describe the bug
A clear and concise description of what the bug is.
Whenever I'm running aplay and arecord in parallel and then stop arecord I will get a DSP crash.
What have you tried to diagnose or workaround this issue?
Tried bisecting, found that 07bf590 breaks it and with the parent commit the playback continues just fine.
To Reproduce
Steps to reproduce the behavior: (e.g. list commands or actions used to reproduce the bug)
-> One terminal, begin arecord. Simplest command is arecord -Dhw:0,0 -f S24_LE -c 2 -r 48000 (to agree with the pipeline and not do any host-side processing but only on DSP if any I used the hw instead of default which is plughw:0,0)
-> The other terminal, begin playback. aplay Sample.wav. My file is S24_3LE which is not supported by SOF so a conversion is necessary, thus I just go with the default. It's also 2 channel, 48k.
-> First terminal, cancel arecord.
-> Listen in the headphones while the song suddenly stops progressing. No errors on aplay but it just hangs in there and I will get IPC errors when attempting to stop.
Reproduction Rate
Consistent (100% of attempts). After each attempt a reboot is required since the DSP is rendered unusable (I presume panic, however my platform doesn't report to the kernel yet; sof-coredump-reader.py reports code 63 which means it's a software initiated panic)
Expected behavior
A clear and concise description of what you expected to happen.
Being able to continue playback.
Impact
What impact does this issue have on your progress (e.g., annoyance, showstopper)
Showstopper.
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: (internal)
- SOF: 468d897
- Name of the topology file
- Topology: sof-imx8qxp-cs42888.m4
- Name of the platform(s) on which the bug is observed.
- Platform: imx8
Screenshots or console output
No particular logs except on the kernel side I get IPC timeout when arecord is stopped, then again when I try to stop aplay.
[ 56.441639] sof-audio-of 596e8000.dsp: error: ipc timed out for 0x60030000 size 12
[ 56.441654] sof-audio-of 596e8000.dsp: error: waking up any trace sleepers
[ 56.441663] Port0: ASoC: trigger FE failed -110
[ 56.953641] sof-audio-of 596e8000.dsp: error: ipc timed out for 0x60030000 size 12
[ 56.953654] sof-audio-of 596e8000.dsp: error: waking up any trace sleepers
[ 114.265642] sof-audio-of 596e8000.dsp: error: ipc timed out for 0x60050000 size 12
[ 114.265657] sof-audio-of 596e8000.dsp: error: waking up any trace sleepers
[ 114.265666] Port0: ASoC: trigger FE failed -110
[ 114.777652] sof-audio-of 596e8000.dsp: error: ipc timed out for 0x60030000 size 12
[ 114.777665] sof-audio-of 596e8000.dsp: error: waking up any trace sleepers
Those with the timestamp of 56 seconds happened when I stopped arecord, those with timestamp 114 were when I also stopped aplay after listening to the tone of 1ms repeating over and over and the song not progressing.
On stopping either aplay or arecord no new logs go through DMA trace. Will edit as soon as I get mailbox trace data.
0 2 IPC 57426298.082583 7879420.500000 src/ipc/handler.c:449 ipc: comp 6 -> trigger cmd 0x50000
0 2 PIPE 2.11 57426307.861862 9.779280 src/audio/pipeline.c:713 pipeline_trigger()
0 2 HOST 2.6 57426313.106607 5.244745 src/audio/host.c:299 host_trigger()
0 2 VOLUME 2.7 57426329.267267 16.160660 udio/volume/volume.c:563 volume_trigger()
0 2 DAI 2.10 57426334.537538 5.270270 src/audio/dai.c:536 dai_comp_trigger(), command = 0
0 2 DMA 57426352.768769 57426352.000000 c/drivers/imx/edma.c:176 EDMA: stop(6)
0 2 SCHEDULE_LL 57426365.312312 12.543544 _multi_chan_domain.c:197 dma_multi_chan_domain_unregister()
0 2 SCHEDULE_LL 57426371.672673 6.360360 _multi_chan_domain.c:173 dma_multi_chan_domain_irq_unregister()
0 2 IPC 57426415.924925 44.252251 src/ipc/handler.c:338 ipc: comp 6 -> free
0 2 PIPE 2.11 57426422.794294 6.869370 src/audio/pipeline.c:788 pipeline_reset()
0 2 HOST 2.6 57426428.617117 5.822823 src/audio/host.c:661 host_reset()
This is the last trace visible in the mailbox; after that I get the timer_domain_register with a timestamp of 852 which is due to wraparound of the trace mailbox itself and is deemed irrelevant.
Attaching full, unfiltered output of sof-logger -l /sof-imx8.ldc -c 666:
etrace.log
Activity
paulstelian97 commentedon Dec 19, 2019
Additionally, stopping aplay while letting arecord running has the same effect.
dbaluta commentedon Dec 19, 2019
@paulstelian97 @akloniex @jajanusz
Actually there is no panic. I suspect there is a deadlock / race introduced by the notifier changes. Can someone at intel try to following simple use case:
jajanusz commentedon Dec 19, 2019
@tlauda @akloniex is it related to that bug with notifier sending msg to wrong core?
paulstelian97 commentedon Dec 19, 2019
@jajanusz On further investigation, I have noticed that I get stuck in an infinite loop in the
list_for_item_safeloop insidenotifier_register. Which is odd to me. I'm watching over the mailbox and I keep seeing a custom trace from that loop filling it up and the timestamps everchanging.I don't see what could corrupt the list to that level. notifier_register and notifier_unregister use spinlocks (without _irq) and are the only things that can modify the list, right? Thus all that I'd expect would be a deadlock instead of this.
paulstelian97 commentedon Dec 19, 2019
On other combinations I have managed to have it actually deadlock on the spinlock notify->lock. That is besides the infinite list BS (where I have
wlist->next == wlistbutwlist->prev != wlist-- yes I'm getting that).i.MX is single core btw (at least for now).
paulstelian97 commentedon Dec 20, 2019
I have new data which I still need to investigate: I think rzalloc returns to the notifier the same address twice without a rfree call inbetween. The only rfree happens in the next block between these. An expert on that, anyone?
etrace dump (DMA trace won't flush due to the while(1) loop inserted upon list corruption being detected)
paulstelian97 commentedon Dec 20, 2019
Found the bug and it's in the memory allocator. Will attempt to push today before leaving for vacation but, if I don't manage, I'll leave the info for someone else to pick up -- apparently the field
first_freebecomes stale for some reason. Do we have (failing) unit tests related to this field?lgirdwood commentedon Dec 20, 2019
@jajanusz possible missing/failing UT for allocator ? See previous message.
paulstelian97 commentedon Dec 20, 2019
An explanation of what I understood of alloc_block and free_block and their usage of first_free.
Let's say we have a heap with two blocks. Initially they are both free:
Now allocate one of the blocks. It will give out the first free block, from where "first_free" points, and will search for the next free block. Nothing wrong with this. It becomes:
Let's also allocate the second block now. No free blocks are found, first_free remains stuck in place. Also, free_count is set to 0 now so get_ptr_from_heap will not even check this heap anymore, so first_free doesn't need to be valid anymore.
Let's free the first block:
Nothing wrong with that, first_free is set correctly in
free_block. Now allocate it again:Fair game, it doesn't need to be valid. Let's free the second block now:
Oops? Since the block is later than where first_free is pointing, this pointer is not updated and suddenly we are in an invalid situation.
If we try to allocate again the FIRST block will now be returned from this heap, which causes havoc.
#2238 is a hacky attempt at fixing it, however from this very explanation I may have uncovered a simpler fix. Will push.
EDIT: Replaced with non-hacky fix which tackles the problem directly. Please review.