[BUG] need to rate-limit 'nothing to copy' traces when mixer source is paused.

[plbossart]

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

[lgirdwood]

@lyakh @keyonjie did one of you work on a PR that updated this message to dbg level ? or a similar fix ?

[marc-hb]

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 detected

[   74.211185] <err> dma_dw_common: xrun detected
[   74.211198] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.212185] <err> dma_dw_common: xrun detected
[   74.212220] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.213185] <err> dma_dw_common: xrun detected
[   74.213208] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.214185] <err> dma_dw_common: xrun detected
[   74.214198] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.215185] <err> dma_dw_common: xrun detected
[   74.215218] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.216186] <err> dma_dw_common: xrun detected
[   74.216208] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.217185] <err> dma_dw_common: xrun detected
[   74.217198] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.218185] <err> dma_dw_common: xrun detected
[   74.218220] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.219185] <err> dma_dw_common: xrun detected
[   74.219208] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.220185] <err> dma_dw_common: xrun detected
[   74.220198] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.221185] <err> dma_dw_common: xrun detected
[   74.221220] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.222185] <err> dma_dw_common: xrun detected
[   74.222208] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.223185] <err> dma_dw_common: xrun detected
[   74.223198] <wrn> dai_comp: comp:3 0x40003 dai_zephyr_copy(): nothing to copy
[   74.223251] <inf> ipc: rx	: 0x13000003|0x1
[   74.223286] <inf> pipe: pipe:2 0x0 pipe trigger cmd 2
[   74.223308] <inf> pipe: pipe:3 0x0 pipe trigger cmd 2
[   74.224253] <inf> ll_schedule: task complete 0xbe0b8bc0 0x20180U
[   74.224273] <inf> ll_schedule: num_tasks 2 total_num_tasks 2
[   74.224340] <err> dma_dw_common: xrun detected
[   74.224360] <inf> ll_schedule: task complete 0xbe0b94c0 0x20180U
[   74.224370] <inf> ll_schedule: num_tasks 1 total_num_tasks 1
[   74.224395] <inf> ll_schedule: zephyr_domain_unregister domain->type 1 domain->clk 4
[   74.230456] <inf> ipc: rx	: 0x13000002|0x1
[   74.230480] <inf> pipe: pipe:3 0x0 pipe trigger cmd 0
[   74.230646] <inf> pipe: pipe:2 0x0 pipe trigger cmd 0
[   74.230681] <wrn> copier: comp:2 0x40002 dai is not ready
[   74.231325] <inf> ipc: rx	: 0x46000002|0x3
[   74.231821] <inf> ipc: rx	: 0x12020000|0x0
[   74.231850] <inf> dma: dma_put(), dma = 0x9e093540, sref = 0
[   74.232636] <inf> ipc: rx	: 0x12030000|0x0
[   74.232870] <inf> dma: dma_put(), dma = 0x9e0934a0, sref = Terminated

[lgirdwood]

@kv2019i any API in Zephyr to rate limit logs ?

[lyakh]

@kv2019i any API in Zephyr to rate limit logs ?

@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]

@kv2019i any API in Zephyr to rate limit logs ?

@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.

Need to use Zephyr methods, SOF logging will go away.

[marc-hb]

@kv2019i any API in Zephyr to rate limit logs ?

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 think either has a special call to mark individual logs for rate-limiting

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)

Need to use Zephyr methods, SOF logging will go away.

I don't see how one could affect the other.

[marc-hb]

Tentative fix submitted, buried in monster PR #8571