[BUG] [multi-core] FW panic when stream is tested on core 1 on MTL RVP

When Core 1 is enabled by topology for stream 1, test the following cmd: aplay works for the first time but is failed at the second time

root@sh-mtlp-rvp-nocodec-04:~# aplay 48K_Let_It_Go.wav -Dhw:0,1 -d 3;sleep 1;aplay 48K_Let_It_Go.wav -Dhw:0,1 -d 3
Playing WAVE '48K_Let_It_Go.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
Playing WAVE '48K_Let_It_Go.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
aplay: pcm_write:2127: write error: Input/output error

No issue on TGL RVP

FW: branch sof main and mtl-003-stable
Kernel: branch sof-dev + thesofproject/linux#4198
kernel_log.txt
trace.txt

Kernel log:

[   98.517121] 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]
[   98.517996] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0: MOD_SET_DX
[   98.518220] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[   98.518229] Message payload: 00000000: 00000002 00000002
[   98.518233] snd_sof:snd_sof_dsp_core_get: sof-audio-pci-intel-mtl 0000:00:1f.3: Core 1 powered up
[   98.518237] snd_sof:snd_sof_dsp_core_get: sof-audio-pci-intel-mtl 0000:00:1f.3: Core ref 1 
[   98.518243] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11000005|0x100000: GLB_CREATE_PIPELINE
[   99.025987] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x11000005|0x100000
[   99.026000] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   99.026015] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x91000005|0x100000|0x0, target: 0x1b060000|0x0|0x0, ctl: 0x3
[   99.026021] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[   99.026024] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   99.026027] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[   99.026030] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[   99.026041] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[   99.026044] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[   99.026052] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[   99.026054] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   99.026059] sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module pipeline.3
[   99.026069] 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]
[   99.528976] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[   99.528990] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[   99.528998] Message payload: 00000000: 00000002 00000000
[   99.529004] sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets

FW log:

[00:00:03.565,590] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 1
[00:00:03.565,595] <inf> dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power I2SLCTL
[00:00:03.566,001] <inf> ipc: ipc_cmd: rx	: 0x47000000|0x0
[00:00:04.583,588] <inf> ipc: ipc_cmd: rx	: 0x47000000|0x0
[00:00:04.584,705] <inf> ipc: ipc_cmd: rx	: 0x11000005|0x100000
[00:00:04.584,728] <err> os:  ** FATAL EXCEPTION
[00:00:04.584,735] <err> os:  ** CPU 1 EXCCAUSE 9 (load/store alignment)
[00:00:04.584,740] <err> os:  **  PC 0xa006c3ac VADDR 0x60313
[00:00:04.584,745] <err> os:  **  PS 0x50f20
[00:00:04.584,760] <err> os:  **    (INTLEVEL:0 EXCM: 0 UM:1 RING:0 WOE:1 OWB:15 CALLINC:1)
[00:00:04.584,768] <err> os:  **  A0 0xa006c3d8  SP 0xa00e7820  A2 0x60313  A3 0x60323
[00:00:04.584,775] <err> os:  **  A4 0x6006c4fe  A5 0xa00ec540  A6 0xa00e781c  A7 0x400f14fc
[00:00:04.584,781] <err> os:  **  A8 0x6006c510  A9 0xa00ec520 A10 0xa00e781c A11 0x10
[00:00:04.584,788] <err> os:  ** A12 (nil) A13 0x400de6a0 A14 0xfffffffe A15 0x1
[00:00:04.584,793] <err> os:  ** LBEG 0xa0037126 LEND 0xa0037137 LCOUNT 0xa00683e8
[00:00:04.584,798] <err> os:  ** SAR 0x1


Backtrace:0xa006c3a9:0xa00e7820 0xa006c3d5:0xa00e7850 0xa006790c:0xa00e7880 0xa0067ced:0xa00e78a0 0xa0045594:0xa00e78d0 0xa0034e16:0xa00e7900 0xa003311b:0xa00e7930 

[00:00:04.584,853] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 1
[00:00:04.584,858] <err> os: Current thread: 0x400f0b88 (unknown)

Found a hint in kernel driver, try it first

SW control core 0 only, other core is controlled by fw, so it is not related to driver.

a simple debug found that the second core was enabled but exception happen when it process idc interrupt.

Confirmed in firmware-automated-testing.fat framework.
I'm passing logs and repro instruction to dev team

SOF and Zephyr PRs are under review:
#7174
zephyrproject-rtos/zephyr#55182

Another defect fix PR that may related to this problem
#7322

@RanderWang

I see the latest update for set_pipeline_state, but now topology setting make sure that all the pipelines for one stream are on single core, and different streams uses different core. So the change is no useful now. Now the error happens with SET_DX

@RanderWang Is the problem you observe on mtl-005 (f2fec74) same as #7649?

@RanderWang

@RanderWang on 005 multiple set state will now work on all configurations like primary+2x secondary or only single secondary or only several secondary cores

Make great progress, with this change the 005 branch can pass the stress test (the change is based on windows FW). Can any one to check it and improve it ?

diff --git a/soc/xtensa/intel_adsp/ace/multiprocessing.c b/soc/xtensa/intel_adsp/ace/multiprocessing.c
index 0d26fc6139..b966f40236 100644
--- a/soc/xtensa/intel_adsp/ace/multiprocessing.c
+++ b/soc/xtensa/intel_adsp/ace/multiprocessing.c
@@ -124,6 +124,8 @@ void soc_start_core(int cpu_num)
	/* Setting the Power Active bit to the off state before powering up the core. This step is
	 * required by the HW if we are starting core for a second time. Without this sequence, the
	 * core will not power on properly when doing transition D0->D3->D0.
	 */
	DSPCS.capctl[cpu_num].ctl &= ~DSPCS_CTL_SPA;

	/* Checking current power status of the core. */
	while (((DSPCS.capctl[cpu_num].ctl & DSPCS_CTL_CPA) == DSPCS_CTL_CPA)) {
		k_busy_wait(HW_STATE_CHECK_DELAY);
	}

+	DSPCS.bootctl[cpu_num].bctl |= DSPBR_BCTL_WAITIPCG ;

	DSPCS.capctl[cpu_num].ctl |= DSPCS_CTL_SPA;

	/* Waiting for power up */
	while (((DSPCS.capctl[cpu_num].ctl & DSPCS_CTL_CPA) != DSPCS_CTL_CPA) &&
	       (retry > 0)) {
		k_busy_wait(HW_STATE_CHECK_DELAY);
		retry--;
	}

@RanderWang

@RanderWang on 005 multiple set state will now work on all configurations like primary+2x secondary or only single secondary or only several secondary cores

@abonislawski can you check my comments ? thanks!
@marcinszkudlinski @serhiy-katsyuba-intel @kv2019i @lgirdwood FYI.

No such issue on TGL, as we know both cavs & ace share most code, only difference in hw register setting.

@abonislawski

@abonislawski I got such warning with latest 005-branch

-- Generated new /home/rander/zephyr/build-mtl/zephyr/include/generated/sof_versions.h
[77/105] Performing build step for 'smex_ep'
ninja: no work to do.
[80/105] Building C object modules/sof/CMakeFiles/modules_sof.dir/home/rander/zephyr/sof/src/idc/idc.c.obj
/home/rander/zephyr/sof/src/idc/idc.c:290:8: warning: implicit declaration of function 'set_pipeline_state' is invalid in C99 [-Wimplicit-function-declaration]
        ret = set_pipeline_state(ppl_icd, cmd, &delayed);
              ^
1 warning generated.

@abonislawski

@abonislawski can you check my comments ? thanks!

On 005 we enabled clock gating by default (WAITIPCG), looks like it should be disabled in multicore scenario? @tmleman

@RanderWang

@RanderWang I looked at this and looks like DSPBR_BCTL_WAITIPCG is already enabled for secondary core in soc_mp_startup(), so the difference is when it is enabled, before or after power up. Potentially this could be our issue.
I moved this registry setup out of soc_mp_startup() to earliest moment in soc_start_core() (like in your test change), please verify this test branch, we can push this to 005 if it will pass
https://github.com/abonislawski/sof/tree/mtl-005-drop-stable
@keqiaozhang please also verify #7649 on this branch

@abonislawski

@abonislawski With your branch, the stress test will be failed after device reboot, but pass stress test after reloading driver.

@keqiaozhang

According to @keqiaozhang test, Current Main branch can pass the stress test without any change.

@RanderWang

@RanderWang clock gating is disabled on main branch, you can revert this from 005 and it will work too

Verified today 2 working solutions:

Rander proposal with DSPBR_BCTL_WAITIPCG without removing WAITIPCG soc_mp_startup()
Set DSPBR_BCTL_WAITIPCG for core 0 when more than one core used

For now pushed Rander proposal to my 005 branch but on main we need to develop correct clock gating management.
https://github.com/abonislawski/sof/tree/mtl-005-drop-stable

@abonislawski

@abonislawski Thanks! I tested for a few hours. 005branch can pass my test script. But I found a new way to reproduce the bug: power off the mtl rvp and boot up it after a few seconds, then I can reproduce it at the first test. I will set up another bug for this behavior. We can close this bug for current state.

Navigation Menu

Repository navigation

[BUG] [multi-core] FW panic when stream is tested on core 1 on MTL RVP #7108

18 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] [multi-core] FW panic when stream is tested on core 1 on MTL RVP #7108

Description

Activity

RanderWang commented on Feb 16, 2023

RanderWang commented on Feb 16, 2023

RanderWang commented on Feb 17, 2023

mszleszy commented on Feb 17, 2023

RanderWang commented on Mar 20, 2023

marcinszkudlinski commented on Mar 22, 2023

18 remaining items

mengdonglin commented on May 19, 2023

abonislawski commented on May 19, 2023

RanderWang commented on May 19, 2023

RanderWang commented on May 19, 2023

RanderWang commented on May 19, 2023

RanderWang commented on May 19, 2023

abonislawski commented on May 19, 2023

abonislawski commented on May 22, 2023

RanderWang commented on May 23, 2023

RanderWang commented on May 23, 2023

abonislawski commented on May 23, 2023

abonislawski commented on May 23, 2023

RanderWang commented on May 24, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions