[BUG][CI] dsp panic on BDW and BYT

[aiChaoSONG]

Describe the bug
In CI daily and PR test, DSP panic is observed on BDW_WSB_RT286, BYT_MB_RT5682 and BYT_MB_NOCODEC

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {topic/sof-dev ef5a473d}
   • SOF: {master adc8cc2}
2. Name of the topology file
   • Topology: {sof-bdw-rt286.tplg on BDW, sof-byt-rt5682.tplg and sof-byt-nocodec.tplg on BYT}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {BDW, BYT}

check the PR test result here: https://sof-ci.01.org/sofpr/PR3100/build6522/devicetest/

dmesg

sh-bdw-wsb-rt286-02 kernel: [  119.134258] sof-audio-acpi INT3438:00: generating page table for 000000000bc36d8b size 0xff00 pages 16
sh-bdw-wsb-rt286-02 kernel: [  119.134261] sof-audio-acpi INT3438:00: stream_tag 0
sh-bdw-wsb-rt286-02 kernel: [  119.134273] sof-audio-acpi INT3438:00: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
sh-bdw-wsb-rt286-02 kernel: [  119.636706] sof-audio-acpi INT3438:00: error: ipc timed out for 0x60010000 size 108
sh-bdw-wsb-rt286-02 kernel: [  119.636715] sof-audio-acpi INT3438:00: info: preventing DSP entering D3 state to preserve context
sh-bdw-wsb-rt286-02 kernel: [  119.636792] sof-audio-acpi INT3438:00: error: assertion failed
sh-bdw-wsb-rt286-02 kernel: [  119.636796] sof-audio-acpi INT3438:00: error: trace point 80000000
sh-bdw-wsb-rt286-02 kernel: [  119.636800] sof-audio-acpi INT3438:00: error: panic at ...pcm_converter/pcm_converter.c�:31
sh-bdw-wsb-rt286-02 kernel: [  119.636804] sof-audio-acpi INT3438:00: error: DSP Firmware Oops
sh-bdw-wsb-rt286-02 kernel: [  119.636809] sof-audio-acpi INT3438:00: EXCCAUSE 0x0000003f EXCVADDR 0x00000000 PS       0x00060725 SAR     0x00000000
sh-bdw-wsb-rt286-02 kernel: [  119.636814] sof-audio-acpi INT3438:00: EPC1     0x00000000 EPC2     0x00000000 EPC3     0x0001a885 EPC4    0x00000000
sh-bdw-wsb-rt286-02 kernel: [  119.636818] sof-audio-acpi INT3438:00: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
sh-bdw-wsb-rt286-02 kernel: [  119.636822] sof-audio-acpi INT3438:00: EPS2     0x00000000 EPS3     0x00060520 EPS4     0x00000000 EPS5    0x00000000
sh-bdw-wsb-rt286-02 kernel: [  119.636826] sof-audio-acpi INT3438:00: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00002040
sh-bdw-wsb-rt286-02 kernel: [  119.636830] sof-audio-acpi INT3438:00: stack dump from 0x0040bd30
sh-bdw-wsb-rt286-02 kernel: [  119.636837] sof-audio-acpi INT3438:00: 0x0040bd30: 00000000 0040bd30 0040bd50 00000028
sh-bdw-wsb-rt286-02 kernel: [  119.636843] sof-audio-acpi INT3438:00: 0x0040bd34: 74726576 632e7265 0000001f 00418e00
sh-bdw-wsb-rt286-02 kernel: [  119.636848] sof-audio-acpi INT3438:00: 0x0040bd38: bff4a600 2b68b6fa 410ac028 ffff95c4
sh-bdw-wsb-rt286-02 kernel: [  119.636853] sof-audio-acpi INT3438:00: 0x0040bd3c: 4201b568 ffff95c4 c054ee24 ffffffff
sh-bdw-wsb-rt286-02 kernel: [  119.636857] sof-audio-acpi INT3438:00: 0x0040bd40: 41d238d8 ffff9b0a bff4a600 2b68b6fa
sh-bdw-wsb-rt286-02 kernel: [  119.636862] sof-audio-acpi INT3438:00: 0x0040bd44: c054eec7 ffffffff a753df45 60010000
sh-bdw-wsb-rt286-02 kernel: [  119.636867] sof-audio-acpi INT3438:00: 0x0040bd48: c054ef6c ffffffff 00000001 00000000
sh-bdw-wsb-rt286-02 kernel: [  119.636872] sof-audio-acpi INT3438:00: 0x0040bd4c: 43ab1228 ffff95c4 c055043a ffffffff
sh-bdw-wsb-rt286-02 kernel: [  119.636878] sof-audio-acpi INT3438:00: error: ipc host -> DSP: pending yes complete no raw 0x80000000
sh-bdw-wsb-rt286-02 kernel: [  119.636882] sof-audio-acpi INT3438:00: error: mask host: pending no complete no raw 0x7fff0000
sh-bdw-wsb-rt286-02 kernel: [  119.636886] sof-audio-acpi INT3438:00: error: ipc DSP -> host: pending no complete yes raw 0x4dead00b
sh-bdw-wsb-rt286-02 kernel: [  119.636890] sof-audio-acpi INT3438:00: error: mask DSP: pending no complete no raw 0x7f9e0000
sh-bdw-wsb-rt286-02 kernel: [  119.636894] sof-audio-acpi INT3438:00: error: waking up any trace sleepers
sh-bdw-wsb-rt286-02 kernel: [  119.636904] sof-audio-acpi INT3438:00: error: hw params ipc failed for stream 0
sh-bdw-wsb-rt286-02 kernel: [  119.636912] sof-audio-acpi INT3438:00: ASoC: error at snd_soc_pcm_component_hw_params on INT3438:00: -110
sh-bdw-wsb-rt286-02 kernel: [  119.636920] sof-audio-acpi INT3438:00: error: trace IO error
sh-bdw-wsb-rt286-02 kernel: [  119.636923]  Low Latency: ASoC: hw_params FE failed -110
sh-bdw-wsb-rt286-02 kernel: [  119.636937] sof-audio-acpi INT3438:00: pcm: free stream 0 dir 1
sh-bdw-wsb-rt286-02 kernel: [  119.638233] sof-audio-acpi INT3438:00: pcm: close stream 0 dir 1

sof-logger.txt

[lgirdwood]

Thanks @aiChaoSONG I see this too now that the Jenkins CI is back, it was off for the last few days... I want to make Jenkins mandatory again. Can you bisect - it should be a recent commot from this week or last.

[plbossart]

FWIW, Baytrail/Cherrytrail worked fine with the topology changes on top of commit 5441b13 ('ipc: component free fix')

That may help with the bisect?

[aiChaoSONG]

@lgirdwood @plbossart @ktrzcinx Bisect result: 1f092df

dmesg already tells us where error occured.

[  119.636706] sof-audio-acpi INT3438:00: error: ipc timed out for 0x60010000 size 108
[  119.636715] sof-audio-acpi INT3438:00: info: preventing DSP entering D3 state to preserve context
[  119.636792] sof-audio-acpi INT3438:00: error: assertion failed
[  119.636796] sof-audio-acpi INT3438:00: error: trace point 80000000
[  119.636800] sof-audio-acpi INT3438:00: error: panic at ...pcm_converter/pcm_converter.c�:31

[lgirdwood]

@ktrzcinx should not enough free/avail really be fatal here ? It's probably best if we trace_err() here instead and return.

void pcm_convert_as_linear(const struct audio_stream *source, uint32_t ioffset,
			   struct audio_stream *sink, uint32_t ooffset,
			   uint32_t samples, pcm_converter_lin_func converter)
{
	const int s_size_in = audio_stream_sample_bytes(source);
	const int s_size_out = audio_stream_sample_bytes(sink);
	char *r_ptr = audio_stream_get_frag(source, source->r_ptr, ioffset,
					    s_size_in);
	char *w_ptr = audio_stream_get_frag(sink, sink->w_ptr, ooffset,
					    s_size_out);
	int i = 0;
	int chunk;
	int N1, N2;

	assert(audio_stream_get_avail_samples(source) >= samples + ioffset);
	assert(audio_stream_get_free_samples(sink) >= samples + ooffset);

[ktrzcinx]

@lgirdwood it can be easily change to tr_err() and return, but I believe that runtime validation with if should be done in higher layers of FW, where some action may be taken, assertion is here only for debug purposes. Otherwise we end up with "noised output" and don't really know where problem comes from.

[lgirdwood]

@ktrzcinx ok - I'm fine if the check is done by the caller (as it can give us more context), but using an assert for debug is probably a bit of overkill. Can you send a PR for the tr_err() and remove the assert() Thanks !

[plbossart]

Didn't we decide already that assert() is not permitted in SOF firmware code?

[lgirdwood]

Didn't we decide already that assert() is not permitted in SOF firmware code?

Good point - although I may have missed that conversation but I agree, if it's not fatal then we should just report and fail.

[plbossart]

IIRC it was a thread with @dbaluta and/or @paulstelian97 on removing asserts - maybe 4-6 months ago?

[paulstelian97]

My statement back then was not completely removing asserts, but considering them unreliable as once the Zephyr migration is complete asserts can be disabled. Asserts also should ONLY be used to catch programming errors that are caused internally in the firmware itself, not programming errors of the kernel or topologies with an invalid configuration; for those regular error reporting (return a negative error code, send an IPC with said negative error code and so on) is better.

In here, it is not clear to me why it would be a firmware programming error the situation where those buffers are too full. So I'd vote for an error return (-EINVAL, -ENOSPC or whichever fits this one most -- do you have better ideas?) coupled with an error trace (do check if they cause spam in the traces though, they probably shouldn't).

Asserts should be used, though only sparingly, given the above in mind, at least in my opinion.

[plbossart]

@paulstelian97 given that 90% of the flows happen due to configurations sent by kernel/topology I am not sure how we might identify internal programming errors...

[paulstelian97]

@paulstelian97 given that 90% of the flows happen due to configurations sent by kernel/topology I am not sure how we might identify internal programming errors...

As such asserts should be a rarity. You could assert certain things about the validity of the output data. I can assert in my DMA driver that I get the proper form of descriptors from SOF or that the hardware is in a certain state. Those aren't directly controllable by the kernel so they should always be in a reasonable state, unless firmware-only programming errors occurred.

But I do agree with the sentiment that this is a rarity and asserts shouldn't be out there too much.