[BUG] Crash at teardown phase when SRC is running as DP component on different core than the rest of the pipeline

[jsarha]

Crash at SRC tear down phase when run as DP component on different core that rest of the pipeline

To Reproduce
Get an MTL (probably any ipc4 nocodec platform would do) device and configure it for nocodec operation. Build topologies from #10009 and copy freshly built sof-mtl-nocodec-dp-core-test.tplg to sof-mtl-nocodec.tplg's place on DUT.

Boot or reload SOF driver. When SOF driver has loaded take the SOF logs with mtrace-reader.py and run:

aplay -Dhw:0,2 -f S32_LE -c 2 -r 44100 -d 10 -t raw /dev/random & arecord -Dhw:0,2 -f S16_LE -c 2 -r 32000 -d 10 /dev/null

Reproduction Rate
So far 100%. But this only happens if the SRC is put on a different core than the rest of the pipeline.

Expected behavior
DSP crashes (panic called), and the code does not continue. I have no stack trace, but according to my studies the failure happens here:

sof/zephyr/lib/regions_mm.c

Line 590 in b193c48

if (!ptr_range_found)

Panic is called here due to the failure:

sof/zephyr/lib/alloc.c

Line 262 in b193c48

k_panic();

And the likely call ending up here:

sof/zephyr/lib/alloc.c

Line 528 in b193c48

void rfree(void *ptr)

The free_src() was recently called, but I have been able to see a print placed at the end of free_src() suggesting that the problematic rfree() call is not done in the module code, but on some higher level.

Impact
This effectively prevents running components (in DP domain) on separate core from rest of the pipeline.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {dee62092621e3cca2080a962cfaec2af1627712d} or later (Should have ASoC: sof: ipc4-topology: Add support to sched_domain attribute linux#5382)
   • SOF: {5a1d8df} for FW, topology needs Topology2: Add nocodec DP core 1 test topologies for MTL, LNL, and PTL #10009
2. Name of the topology file
   • Topology: {sof-mtl-nocodec-dp-core-test.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {MTL}

Screenshots or console output
'''
[ 615.237115] ipc: ipc_cmd: rx : 0x12000000|0x0
[ 615.237341] dma: sof_dma_put: dma_put(), dma = 0x400c9770, sref = 0
[ 615.238336] ipc: ipc_cmd: rx : 0x12010000|0x0
[ 615.238623] src: src_free: comp:1 0x9 src_free()
[ 615.238913] mem_allocator: virtual_heap_free: Unable to free 0xa0158000
'''
In kernel logs it looks like this
'''
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules mixin.5.1:0 -> mixout.6.1:0
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x46000003|0x4: MOD_UNBIND
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x46000003|0x4
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to unbind modules mixin.5.1:0 -> mixout.6.1:0
May 19 13:35:47 9049fa08cb7e.jf.intel.com kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x12020000|0x0: GLB_DELETE_PIPELINE
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x12020000|0x0
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to free pipeline widget pipeline.5
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx : 0x47000000|0x0: MOD_SET_DX [data size: 8]
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
May 19 13:35:48 9049fa08cb7e.jf.intel.com kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to disable target core: 1 for pipeline pipeline.5
'''

[marcinszkudlinski]

@jsarha can you please provide a diagram of a topology used in the test? So far I checked 2 pipelines:

copier (LL, core0) --> SRC (DP, core1) --> copier (LL core0)
and
copier (LL, core0) --> SRC (DP, core1) --> copier (LL core0) --> SRC (DP, core2) --> copier (LL core0)

and both are working fine, no issues nor crashes in pipeline teardown

[jsarha]

@marcinszkudlinski my staring point was a little different since the SRC and the pipeline was originally running on core 2, from where I moved it to core 1. The full pipeline looks like this

copier (LL, core 2) -> gain (LL, core 2) -> src (DP, core 1) -> mixin (LL, core 2) -> mixout (LL, core 2) -> gain (LL, core 2) -> copier (LL, core 2)
And at the same time there is another pipeline for capture:
copier (LL, core 2) -> src (DP, core 1) -> copier (LL, core 2)

[jsarha]

The failed rfree() call originates here:

sof/src/audio/buffers/ring_buffer.c

Line 98 in b193c48

rfree((__sparse_force void *)ring_buffer->_data_buffer);

[jsarha]

To get a different angle I moved my testing to my up14 (my other platform is a Onecloud RVP nest MTL RVP), and there the behaviour is a bit different, and some times the SRC DP component on different core fails much earlier with various symptomps, but sometimes I see the rfree() from ring_buffer_free() crahsing there too. SRC DP component on same core as the rest of the pipeline works fine on up14 too.

[jsarha]

The stream that deterministically gives the same error that I have been tracking on both platforms is capture stream alone. e.g. :
dai copier (LL, core 2) -> src (DP, core 1) -> host copier (LL, core 2)

The playback stream alone crashes too, but it does not give too many hints on what went wrong.

[marcinszkudlinski]

I's looks like a race when deleting a pipeline - or rather when deleting multiple pipelines

/**
 * @brief remove the queue from the list, free memory
 */
static void ring_buffer_free(struct sof_audio_buffer *audio_buffer)
{
	if (!audio_buffer)
		return;

	struct ring_buffer *ring_buffer =
			container_of(audio_buffer, struct ring_buffer, audio_buffer);

	rfree((__sparse_force void *)ring_buffer->_data_buffer);
}

So far no luck with a reproduction on my side, but looking at the above I see that

• there's no chance for null dereference there (unless core 1 change something when core 0 is in the procedure above)
• there's no setting ring_buffer->_data_buffer to null after freeing, so it may lead to use after free in case of races.

can you please check again adding one line: ring_buffer->_data_buffer = NULL

/**
 * @brief remove the queue from the list, free memory
 */
static void ring_buffer_free(struct sof_audio_buffer *audio_buffer)
{
	if (!audio_buffer)
		return;

	struct ring_buffer *ring_buffer =
			container_of(audio_buffer, struct ring_buffer, audio_buffer);

	rfree((__sparse_force void *)ring_buffer->_data_buffer);
	ring_buffer->_data_buffer = NULL;
}

[jsarha]

@marcinszkudlinski the null assignment did not change the behaviour. The recording stream tear-down still crashes the DSP on the both MTL platforms I tested it on. The crash happens in the same place:

sof/zephyr/lib/regions_mm.c

Line 590 in b193c48

if (!ptr_range_found)

and the rfree() originates from the same place:

sof/src/audio/buffers/ring_buffer.c

Line 98 in b193c48

rfree((__sparse_force void *)ring_buffer->_data_buffer);

Here is also a full mtrace of the situation. I have removed some prints in src_reset() and src_free() not to fill up the mtrace buffer at the critical moment just before the crash:
sof-bug-10024-mtrace.txt

[jsarha]

@marcinszkudlinski to reproduce the bug, it is important that the LL components, the copiers, are not running on core 0. If I move the copiers to core 0 I do not see the bug any more either. E.g. this is setup reproduces the bug:

copier (LL, core 2) -> src (DP, core 1) -> copier (LL, core 2)

[jsarha]

@marcinszkudlinski , according to my debugging the problem is probably that a ring buffer is allocated on core 0, but its freed on core 2. I see if can follow the code to find where that happens, but you can probably find it much easier.

[jsarha]

My feeble attempt to fix this by creating new IDC for freeing a buffer pointer on some other core failed (is it at all possible to send IDC from other cores to core 0?), but revealed that much that even if the ring buffers reserved on other cores are not freed at all, there will still be a ring buffer free failure eventually.

[marcinszkudlinski]

@marcinszkudlinski , according to my debugging the problem is probably that a ring buffer is allocated on core 0, but its freed on core 2. I see if can follow the code to find where that happens, but you can probably find it much easier.

That should be fine, as long as RingBuffer is allocated as "shared". In this case all buffer's structures, with exception of the data itself, are located in uncached memory alias. Non-cached alias for data also should not be an issue as Zephyr suppose to handle cross core alloc/free properly (although the way Zephyr does it costs a lot of memory)
Anyway, it crashes when freeing a cached alias. There were some optimalizations in memory allocation area lately and maybe cross core alloc/free is no longer working? I'll focus on this.