zephyr: audio: host: Fix "no bytes to copy" log supressing

[softwarecki]

Display the number of previously skipped log entries before displaying a new entry about no bytes to copy. Restart nobytes_last_logged after displaying the number of skipped messages.

Log before change:

[    4.011990] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.013016] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms
[    4.014370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 2 ms
[    4.015036] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 3 ms
[    4.016370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 4 ms
[    4.017036] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 5 ms
[    4.018370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 6 ms
[    4.019040] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 7 ms
[    4.020370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 8 ms
[    4.021036] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 9 ms
[    4.022370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 10 ms
[    4.023016] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 11 ms
[    4.024203] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 12 ms
[    4.025370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 13 ms
[    4.026016] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 14 ms
[    4.027203] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 15 ms
[    4.028370] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 16 ms
[    4.029016] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 17 ms
[    4.030286] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 18 ms
[    4.031453] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 19 ms
[    4.032036] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 20 ms

after:

[    4.013091] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.013715] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.014925] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.015711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.016756] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.017711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.019091] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.019711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.021091] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.021748] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.023091] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.023711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.025091] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.025711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.027090] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.027780] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.029175] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.029711] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.031008] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64
[    4.031710] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 no bytes to copy, available samples: 0, free_samples: 192
[    4.032756] <wrn> host_comp: host_get_copy_bytes_normal: comp:2 0x10003 Skipped 1 no-bytes events in last 1 ms, bytes 64

The above fragments are from the kpb test. When draining the history buffer, the host copy function is called twice per period. Once by the pipeline and once by the draining task.

[Copilot]

Pull Request Overview

This PR fixes log suppression for no-bytes events in the Zephyr audio host by displaying the number of skipped events and associated byte count before logging a new no-bytes event.

• Recalculates the reset condition for skipped events using the elapsed time since the last log.
• Updates the log message format and reorders the logic for resetting and incrementing the skipped counter.

[Copilot]

[nitpick] Consider restructuring the incrementation of hd->n_skipped by moving the increment into an else clause. This would clarify that the increment is intended only when no logging occurs, improving readability.

[dbaluta]

Thanks @softwarecki this is super useful. I wonder if we can make it generic under a function named dev_warn_ratelimit for example.

[lyakh]

@softwarecki how realistic is actually the kpb test? If this is a practically feasible flow, then we probably shouldn't complain about "no bytes" every millisecond? And after your changes even with 2 messages per millisecond. The output does potentially look nicer, but I'm wondering whether in realistic scenarios it really would increase logging output a lot?

[lgirdwood]

Zephyr may have plans for rate limited logging... might be worth inquiring, but this is good now.

[softwarecki]

@lyak: The goal of this PR is to improve the mechanism of skipping log messages. Since they look nicer, it means the goal has been achieved. :)

The way kpb works (host is starved until a keyword is detected, which causes the log to be spammed with "no bytes" entries) is beyond my interest at the moment.