Repository navigation
[BUG] IPC error during pause/start test with multiple mixer sources #3522
Description
Initially filed as a Linux bug since the result is an IPC error, now transferred to SOF.
I've seen this error multiple times with sof-test, this is not a random error but a mixer issue from the logs.
@lgirdwood @lyakh @singalsu FYI
Log files: multiple-pause-resume.tar.gz
excerpts:
dmesg:
kernel: [ 531.157632] sof-audio-acpi 808622A8:00: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
kernel: [ 531.157787] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
kernel: [ 531.317334] sof-audio-acpi 808622A8:00: pcm: trigger stream 0 dir 0 cmd 3
kernel: [ 531.317358] sof-audio-acpi 808622A8:00: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 531.317486] sof-audio-acpi 808622A8:00: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
kernel: [ 531.417219] sof-audio-acpi 808622A8:00: pcm: trigger stream 1 dir 0 cmd 1
kernel: [ 531.417276] sof-audio-acpi 808622A8:00: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
kernel: [ 531.417408] sof-audio-acpi 808622A8:00: error: ipc error for 0x60040000 size 12
kernel: [ 531.417435] sof-audio-acpi 808622A8:00: ASoC: error at snd_soc_pcm_component_trigger on 808622A8:00: -22
kernel: [ 531.417450] PCM Deep Buffer: ASoC: trigger FE cmd: 1 failed: -22
kernel: [ 531.417472] sof-audio-acpi 808622A8:00: pcm: trigger stream 1 dir 0 cmd 0
etrace:
TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[ 8250820.781250] ( 8250821.000000) c0 dma-trace src/trace/dma-trace.c:327 ERROR FW ABI 0x3012000 DBG ABI 0x5002001 tag v1.5-rc1-778-ge5d17f3c10f3 src hash 0xa3b71c81 (ldc hash 0xa3b71c81\
)
[531415530.364583] (523164704.000000) c0 mixer 1.1 src/audio/component.c:190 ERROR comp_set_state(): wrong state = 4, COMP_TRIGGER_START
[531415540.364583] ( 10.000000) c0 pipe 4.25 src/audio/pipeline.c:884 ERROR pipeline_trigger(): ret = -22, host->comp.id = 21, cmd = 1
[531415563.750000] ( 23.385416) c0 ipc src/ipc/handler.c:443 ERROR ipc: comp 21 trigger 0x40000 failed -22
```
Activity
[-][BUG][CHT] IPC error during multiple pause-push/pause-release test with Deep Buffer PCM[/-][+][BUG][CHT] IPC error during multiple pause/resume test with Deep Buffer PCM[/+]plbossart commentedon Oct 14, 2020
This seems like a fundamental flaw in the mixer logic. The error is that a TRIGGER_START is send while the component is in COMP_STATE_PAUSED state (value 4)
This is however perfectly possible that an existing mixer source is paused, and a new mixer source starts with a TRIGGER_START.
plbossart commentedon Oct 14, 2020
This bug is 100% reproducible.
Connect with the target with two terminals.
Terminal1:
then press space to pause
Terminal 2:
that should start playback for the second device, however the results are an error
dmesg log
etrace:
plbossart commentedon Oct 14, 2020
moving to sof issue since it's clearly a mixer state machine bug in the firmware.
plbossart commentedon Oct 14, 2020
@ranj063 can you help identify which platforms expose PCM devices that get mixed? I only see byt/cht for now. Thanks!
ranj063 commentedon Oct 14, 2020
@plbossart apart from the byt/cht codec topologies, the byt/cght nocodec and apl nocodec topologies have mixer based PCMs
plbossart commentedon Oct 14, 2020
@ranj063 who is the platform owner for Up2 nocodec? that bug should also impact that device.
fredoh9 commentedon Oct 14, 2020
@marc-hb is owner of APL_UP2_NOCODEC platform
plbossart commentedon Oct 14, 2020
I actually don't see any mixers in the apl-nocodec topology
marc-hb commentedon Oct 14, 2020
I'm the UP2 platform owner but I stuck to pcm512x so far. Finding a magic system configuration (BIOS version, ACPI override, topology, kernel config,...) that actually produced some sound was by far the most time-consuming part of the "SOF rite of passage" and a Zephyr detour + the lack of firmware loader logs made it even more painful so I avoided any configuration change so far to focus on more productive things. Let me know if/when I should bite the bullet.
fredoh9 commentedon Oct 14, 2020
I saw a mixer in APL NOCODEC
ranj063 commentedon Oct 14, 2020
clearly someone missed updating this when they added the mixer. I wonder if that was me
plbossart commentedon Oct 14, 2020
The Kconfig FORCE_NOCODEC is your friend. It will ignore whatever you've setup with ACPI overrides, etc, you don't need to change anything on the device itself - except making sure the sof-apl-nocodec.tplg file is present on the disk.
plbossart commentedon Oct 15, 2020
@mmaka1 the state diagram in https://thesofproject.github.io/latest/developer_guides/firmware/components/component-overview.html#handle-the-component-device-state cannot work for a mixer component. When the mixer component is paused, it should go back to active when a new source starts. The trigger_release isn't the only stimulus to go from paused to active.
49 remaining items
cujomalainey commentedon Jan 16, 2021
From here. So appears the only solution is to not have someone put in the keyword
lgirdwood commentedon Jan 18, 2021
@marc-hb this is not an auto-closed bug. @slawblauciak had confirmed fix.
It sounds like you are suggesting we need an extra step where someone from CI confirms that the test for bug X has passed CI for the past Y days and than can either label the issue or close the issue ? This labelling confirmation could also be automated if we could link bugs to CI in GH somehow ???
marc-hb commentedon Jan 18, 2021
Sorry, I thought it was auto-closed by github because of the timing and because there is (still) no clear indication of what testing was performed.
Yes some extra step like this but only for bugs with no deterministic CI reproduction like this one. Simpler bugs can be closed immediately.
OK, then it's never going to work :-( We'll just have to not blindly trust the "closed" status of bugs.
marc-hb commentedon Jan 19, 2021
multiple-pause-resume.shfailed again in internal nightly validation run 1679 and the failure was linked to this bug. It failed on only one device. It was validating most recent commit e17b90d which includes tentative fix #3618There are plenty of logs but I don't know enough about this bug to tell from them whether that failure was actually this bug.
lgirdwood commentedon Jan 19, 2021
@marc-hb so do you have any thoughts on how we could reference a GH issue against a CI test. We already have an interface where we can tell CI to test a PR via a comment, but I've no idea if this can be done for bugs e.g.
SOFCI test=id1,id2(cml)Which could tell CI that this issue is tested by tests id1 (all platforms) and id2 (on cml) and then CI could report once it was passing for a time period.
marc-hb commentedon Jan 19, 2021
I don't know how we would do this and I'm sorry I derailed this (important) bug. I don't think we're struggling and need some automation to help us close bugs. So far I only observed the opposite: bugs closed (by github or manually) without process or validation details. Today's example: thesofproject/linux#1449 (comment)
cujomalainey commentedon Jan 19, 2021
You can tell if it was closed automatically by the closing line. E.g.
Automatically
jajanusz closed this in #2148 on Dec 16, 2019Manual
cujomalainey closed this on Dec 3, 2020marc-hb commentedon Jan 21, 2021
This is apparently not #3522 after all but #3714
I still feel like the testing for #3522 is scant but at least it didn't seem to have surfaced recently.
EDIT: Multiple PRs required to fix one bug: another example where auto-closing backfires: #3732 (comment) I will personally stop using the magic
Fixes: 1234syntax; every little helps.slawblauciak commentedon Feb 26, 2021
Is this issue reproducible still?
marc-hb commentedon Feb 27, 2021
Hard to tell as long a
multiple-pause-resume.shis still not reliable for other reasons like #3714 or #3837.multiple-pause-resume.shwas barely reproducing this bug in the first place and I haven't seen any other test for it, is there?plbossart commentedon Jun 10, 2021
@lgirdwood @marc-hb I haven't seen any failures for pause/resume tests on platforms with a mixer, should we close this?
marc-hb commentedon Jun 10, 2021
OK so I did the simple thing what everyone in either development or validation should always do to "test the test" but apparently never ever does because we love our green failures: I simply reverted the fix dcbee3c (minor conflict, easily solved) and ran the test again on my UP2. It fails on PCM7 like this:
Is this close enough to the original issue which I didn't try to understand? If yes then this can be closed.
Note when the test is passing it still prints this other green failure which seems unrelated:
Should this other error be filed elsewhere?
plbossart commentedon Jun 10, 2021
we see this sort of logs all the time with pause_push/release and suspend/resume while playing back. I don't think this is problematic.
Let's close this, thanks for the feedback @marc-hb