Repository navigation
[BUG] need to rate-limit 'nothing to copy' traces when mixer source is paused. #4672
Description
Describe the bug
When we use a mixer, pausing while using a single source will cause a lot of trace messages
[ 16189998.887917] ( 1237.760376) c0 dw-dma src/drivers/dw/dma.c:1069 INFO dw_dma_free_data_size() size is 0!
[ 16190010.710833] ( 11.822916) c0 dai 1.2 src/audio/dai.c:957 WARN dai_copy(): nothing to copy
[ 16191249.200368] ( 1238.489502) c0 dw-dma src/drivers/dw/dma.c:1069 INFO dw_dma_free_data_size() size is 0!
[ 16191261.127450] ( 11.927083) c0 dai 1.2 src/audio/dai.c:957 WARN dai_copy(): nothing to copy
[ 16192498.991985] ( 1237.864502) c0 dw-dma src/drivers/dw/dma.c:1069 INFO dw_dma_free_data_size() size is 0!
[ 16192510.814901] ( 11.822916) c0 dai 1.2 src/audio/dai.c:957 WARN dai_copy(): nothing to copy
[ 16193749.200268] ( 1238.385376) c0 dw-dma src/drivers/dw/dma.c:1069 INFO dw_dma_free_data_size() size is 0!
This is due to the fact that we don't pause a mixer but keep it active.
To Reproduce
use a topology with a mixer, e.g. cavs-nocodec
aplay -Dhw:0,0 -c2 -r48000 -fS16_LE /dev/zero -vv -i
press space bar
in another terminal, run sof-logger
Reproduction Rate
100%
Expected behavior
rate-limit the trace messages in that case. There's nothing to copy because the sources are paused.
Impact
annoyance
Activity
lgirdwood commentedon Dec 13, 2021
@lyakh @keyonjie did one of you work on a PR that updated this message to dbg level ? or a similar fix ?
marc-hb commentedon Jun 9, 2023
Still happening with Zephyr
https://sof-ci.01.org/sofpr/PR7763/build9190/devicetest/index.html?model=TGLU_RVP_SDW_IPC4ZPH&testcase=multiple-pause-resume-
#7763
then this test failed with
[ 74.224340] <err> dma_dw_common: xrun detectedlgirdwood commentedon Jul 4, 2023
@kv2019i any API in Zephyr to rate limit logs ?
lyakh commentedon Jul 5, 2023
@lgirdwood both SOF and Zephyr have means to drop logging entries in case of flooding, SOF also can merge "similar" messages in such situations but I don't think either has a special call to mark individual logs for rate-limiting. I was looking for that recently too and haven't found anything.
lgirdwood commentedon Jul 5, 2023
Need to use Zephyr methods, SOF logging will go away.
marc-hb commentedon Jul 5, 2023
I had a look and I could not find anything either, just "drop newest" vs "drop oldest" when full.
https://docs.zephyrproject.org/latest/services/logging/index.html#log-message-allocation
I don't see when someone would want to rate-limit one specific log statement while letting others flood the logs. EDIT: you could want a higher threshold for some statements versus others, see example in #5597. Except this not really an example because it mentions only one statement, so there's a chance changing global thresholds is still enough even in 5997
The old sof-logger throttling is smart enough to automatically throttle only abusive log statements, leaving other logs unaffected. I'd expect something similar from Zephyr (if there was anything)
I don't see how one could affect the other.
marc-hb commentedon Dec 12, 2023
Tentative fix submitted, buried in monster PR #8571
5 remaining items
kv2019i commentedon Dec 15, 2023
I think this is a bug. If the mixer itself is active, it should continue to produce data to the DAI if the DAI is running. I'll bump priority to P2 and assign to v2.9.
marcinszkudlinski commentedon Dec 15, 2023
I'm still not comfortable with silencing those messages, they have been very useful for me recently
do what do you think about this sollution:
as cycles with no data may naturally happen at pipeline startup, so silence them.
BUT - once a first data portion arrives, any further "no data" cycle means a glitch.
lgirdwood commentedon Dec 19, 2023
@kv2019i your fix now merged, good to close ?
kv2019i commentedon Dec 20, 2023
@lgirdwood I think what @plbossart described here originally is actually a bug, but when I tried to reproduce this today, I could not. Even without my recent fix PR to (8649), pausing PCMs with mixer caused no flood of "nothing to copy" messages. So unless @plbossart disagrees, I think this can be closed. The original functional problem has been solved, and also "nothing to copy" messages are now limited to debug builds only.
plbossart commentedon Dec 20, 2023
I am not sure what to make of all the comments.
This is a 2.5yr old bug, I am not even sure it this was reported in the context of IPC4.
On one side we have our trusted @kv2019i who cannot reproduce the error, and on the other side no consensus with a remark from @marcinszkudlinski and a reference to Google AEC which cannot possibly be related.
I would err on the side of keeping this open until there's consensus.
kv2019i commentedon Jan 12, 2024
@marcinszkudlinski Are you good to close this now? We have kept the warning logs in code, but they are behind a build option (#8649). I think in any case, all known problems (that people can reproduce have been fixed), so I don't want to keep this open for v2.9 if it's not clear anything is broken or needs to be done.
marcinszkudlinski commentedon Jan 15, 2024
for me - ok to close
marc-hb commentedon Jan 18, 2024
The mtrace spam still makes logs unusable.
Try opening
https://sof-ci.01.org/sofpr/PR8754/build1979/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pause-resume-50 ,then click on the "mtrace" tab. The logs are so big that it takes at least 10-15 seconds to just open that tab. Probably longer if you don't have a high speed connection.
kv2019i commentedon Jan 18, 2024
@marc-hb Please open a different bug for this. This is a log coming from different component and in different case, so we are reusing same bug id for multiple issues here. These logs in latest comment are expected, but we can debate the volume.
marc-hb commentedon Jan 18, 2024
Opened new #8761