[BUG]COMP_FREE IPC times out with gcc built FW

Describe the bug
COMP_FREE IPC is sent to the FW when the topology is taken down. Previously, when the SOF device runtime suspends, the DSP is always powered off. So the topology components didnt need to the freed and the COMP_FREE IPC was never used. But with the multi-client implementation in the SOF driver, each client is responsible for freeing the components in the DSP FW when the device suspends. And this leads to IPC time outs quite frequently. But the issue can only be reproduced with the FW built with gcc.

To Reproduce
Build SOF FW with gcc
Run the check-runtime-pm-status.sh test

Reproduction Rate
Easily reproducible within 10 iterations

Expected behavior
No IPC timeouts

Impact
showstopper

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: c47f1bd + PR 1748
- SOF: 30cd56f
Name of the topology file
- Topology: sof-apl-nocodec.tplg
Name of the platform(s) on which the bug is observed.
- Platform: UP2 APL nocodec mode

Screenshots or console output
All results available at https://sof-ci.01.org/linuxpr/PR1748/build3019/devicetest/

@ranj063

@ranj063 I'm not seeing any kernel oops or crash info for the FW. Can you switch this on. But what I have seen so far is that it seems to be very similar trace logs i.e.

    0      2          IPC            348036.979167        37.604168    src/ipc/handler.c:1110	ipc: hdr 0x30010000 tx (76) > rx (28)
    0      2          IPC            348039.687500         2.708333    src/ipc/handler.c:1117	ipc: pipe 11 comp 40 -> new (type 1)
    0      2         HOST            348044.791667         5.104167     src/audio/host.c:354 	host_new()
.....

    0      2          IPC           2490434.895833   1884010.000000    src/ipc/handler.c:484 	ipc: comp 40 -> trigger cmd 0x50000
    0      2         PIPE 11.45     2490437.916667         3.020833 src/audio/pipeline.c:621 	pipeline_trigger()
    0      2         HOST 11.40     2490440.885417         2.968750     src/audio/host.c:300 	host_trigger()
    0      2          DMA           2490444.322917         3.437500 intel/cavs/hda-dma.c:538 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME 11.41     2490448.125000         3.802083 udio/volume/volume.c:584 	volume_trigger()
    0      2          DAI 11.44     2490451.354167         3.229167      src/audio/dai.c:523 	dai_comp_trigger(), command = 0
    0      2          DAI 11.44     2490454.583333         3.229167      src/audio/dai.c:582 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA           2490457.760417         3.177083 src/drivers/dw/dma.c:415 	dw_dma_stop(): dma 0 channel 3 stop
    0      2          SSP           2490461.406250         3.645833 ers/intel/cavs/ssp.c:719 	ssp_trigger() cmd 0
    0      2          SSP           2490508.072917        46.666668 ers/intel/cavs/ssp.c:700 	ssp_stop(), TX stop
    0      2          SSP           2490511.302083         3.229167 ers/intel/cavs/ssp.c:709 	ssp_stop(), SSP port disabled
    0      2  SCHEDULE_LL           2490514.531250         3.229167 hedule/ll_schedule.c:377 	task cancel 0xbe0357c0
    0      2  SCHEDULE_LL           2490518.281250         3.750000 hedule/ll_schedule.c:244 	num_tasks 2 total_num_tasks 2
    0      2          IPC           2490782.760417       264.479156    src/ipc/handler.c:357 	ipc: comp 40 -> free

All the traces I've seen so far trigger comp 40 (Host DMA component) then free comp 40. There is nothing in error log which is suspicious since our exception code should put something there.

@jajanusz @tlauda Any reasons why freeing host DMA component after Trigger STOP would crash/hang the DSP ? Looks racey since it's not been seen yet with XCC.

@ranj063

@ranj063 I'm not seeing any kernel oops or crash info for the FW. Can you switch this on. But what I have seen so far is that it seems to be very similar trace logs i.e.

@lgirdwood what particular options should I switch on? On the kernel side, I'have pretty much everything enabled.

@lgirdwood

@lgirdwood I think the FW logs are out of sync or corrupted. Timestamps are totally messed up and I don't see any COMP_FREE IPC. There are only STREAM_PCM_FREE.

@ranj063 Could you specify which exact component does fail during free operation? I can't tell this from dmesg. Or is it just random?

@tlauda

@tlauda Did you look into etrace (mailbox trace)? On crashes DMA trace tends to lag behind and not show the final logs, at least for me.

@ranj063

@ranj063 Issue still seen?

Lower the priority since this issue cannot be reproduced by xcc.

@mengdonglin

@mengdonglin @ranj063 Can we still reproduce it with gcc?

@ranj063

@ranj063 maybe also worth running the same sequence through the fuzzer.

@ranj063

@ranj063 can you please confirm if it's still a problem?

@fredoh9

issue not reproduced with
"version" : {
"kernelBranch" : "topic/sof-dev",
"kernelCommit" : "20cf8377",
"sofBranch" : "main",
"sofCommit" : "fcaede7a8710"
},

Thanks for test @fredoh9

Navigation Menu

Repository navigation

[BUG]COMP_FREE IPC times out with gcc built FW #2348

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG]COMP_FREE IPC times out with gcc built FW #2348

Description

Activity

lgirdwood commented on Feb 4, 2020

ranj063 commented on Feb 4, 2020

tlauda commented on Feb 5, 2020

paulstelian97 commented on Feb 5, 2020

tlauda commented on Feb 19, 2020

mengdonglin commented on Feb 20, 2020

tlauda commented on Mar 3, 2020

lgirdwood commented on Mar 3, 2020

slawblauciak commented on Sep 1, 2020

ranj063 commented on Jun 3, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions