host_get_copy_bytes_normal: "no bytes to copy" log spam #8761
Comments
|
This is potentially related to (and fixed by) #8756 The "host_get_copy_bytes_norma" logs repeat exactly 10ms which is the delay we now have in set-pipeline-state processing (fixed by 8756). |
|
This massive spam really makes it impossible to do anthing. Try for instance looking at the mtrace logs in https://sof-ci.01.org/sofpr/PR8855/build2720/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pause-resume-50 Good luck. The sheer workload is probably changing timings considerably too, which means turning debug on/off makes reproductions come and go. |
|
@marc-hb can you try the following patch in your failing test case. If it helps then we can upstream. From aad766dc742525df67f579c0b5afadeb0b102244 Mon Sep 17 00:00:00 2001
From: Liam Girdwood <liam.r.girdwood@linux.intel.com>
Date: Mon, 19 Feb 2024 14:11:51 +0000
Subject: [PATCH] host-zephyr: flow control "no data to copy" message.
Flow control the important "no data to copy" message which can be
indicative that an error state has been entered but can also flood the
logs worsening the log SNR for debug.
Signed-off-by: Liam Girdwood <liam.r.girdwood@linux.intel.com>
---
src/audio/copier/host_copier.h | 1 +
src/audio/host-zephyr.c | 16 +++++++++++++---
2 files changed, 14 insertions(+), 3 deletions(-)
diff --git a/src/audio/copier/host_copier.h b/src/audio/copier/host_copier.h
index 08cbba43b..07346a868 100644
--- a/src/audio/copier/host_copier.h
+++ b/src/audio/copier/host_copier.h
@@ -68,6 +68,7 @@ struct host_data {
uint16_t no_stream_position; /**< 1 means don't send stream position */
uint64_t total_data_processed;
uint8_t cont_update_posn; /**< 1 means continuous update stream position */
+ uint8_t dma_copy_info_count; /**! flow control for DMA "no bytes" message */
/* host component attributes */
enum comp_copy_type copy_type; /**< Current host copy type */
diff --git a/src/audio/host-zephyr.c b/src/audio/host-zephyr.c
index fd629838a..3abbba85e 100644
--- a/src/audio/host-zephyr.c
+++ b/src/audio/host-zephyr.c
@@ -397,9 +397,19 @@ static uint32_t host_get_copy_bytes_normal(struct host_data *hd, struct comp_dev
if (!(hd->ipc_host.feature_mask & BIT(IPC4_COPIER_FAST_MODE)))
dma_copy_bytes = MIN(hd->period_bytes, dma_copy_bytes);
- if (!dma_copy_bytes)
- comp_info(dev, "no bytes to copy, available samples: %d, free_samples: %d",
- avail_samples, free_samples);
+ if (!dma_copy_bytes) {
+ /* flow control this message, its important but can flood the logs,
+ * so dial down to ~4 times per second when continual (based on
+ * 1 LL tick per ms and dma_copy_info_count being a uint8_t).
+ */
+ if (hd->dma_copy_info_count++ == 0) {
+ comp_info(dev, "no bytes to copy, available samples: %d, free_samples: %d",
+ avail_samples, free_samples);
+ }
+ } else {
+ /* DMA back to normal now with data to copy so reset counter */
+ hd->dma_copy_info_count = 0;
+ }
/* dma_copy_bytes should be aligned to minimum possible chunk of
* data to be copied by dma.
--
2.40.1 |
|
This is potentially fixed by zephyrproject-rtos/zephyr#69480 . Assigning to @serhiy-katsyuba-intel as owner of the Zephyr fix. |
|
I will skim recent logs, give me some time until next week. |
|
Not fixed. For instance the mtrace tab in https://sof-ci.01.org/sofpr/PR8995/build3690/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pause-resume-50 has still 30,000 lines with That's for just 50 pause/resume iterations. What's new: these lines are not consecutive anymore. |
|
The original issue has been fixed, after talking to the developers, setting the issue to P2 |
wszypelt
added
P2
|
I'm not sure why now, but https://sof-ci.01.org/sofpr/PR9086/build4356/devicetest/index.html?model=MTLP_RVP_NOCODEC&testcase=multiple-pause-resume-50 is still totally unusable (which is why I'm not sure why). Try it. |
|
@marc-hb this won't be fixed in fw. Phrase "no bytes" was found about 33 000 times in 1000 000 log lines. Please close the ticket. |
Protect storage in case this is not run first and immediately after boot as it should. Also makes the logs more relevant and usable: long files can make the user interface unusable, see example in thesofproject/sof#8761 This also gives us --no-pager "for free" in case it was ever needed. Fixes recent commits c8565e8 and 914c5c0. Signed-off-by: Marc Herbert <marc.herbert@intel.com>
Protect storage in case this is not run first and immediately after boot as it should. Also makes the logs more relevant and usable: long files can make the user interface unusable, see example in thesofproject/sof#8761 This also gives us --no-pager "for free" in case it was ever needed. Fixes recent commits c8565e8 and 914c5c0. Signed-off-by: Marc Herbert <marc.herbert@intel.com>
|
@marc-hb could you close the ticket? or maybe the issue is still reproducing? |
|
Still 30,000 "no bytes to copy" spam in https://sof-ci.01.org/sofpr/PR9174/build4946/devicetest/index.html?model=LNLM_SDW_AIOC&testcase=multiple-pause-resume-50 There are 1200 such lines in 1.2 seconds near the end, so the 1 line/ms is probably not a coincidence. |
|
@marc-hb can we implemented log_ratelimit? So that if thare are more that we only alow for about 10 similar logs in about 1s? |
|
@dbaluta pls go ahead with ratelimit. Thanks ! |
|
I don't know what changed but the logs are usable now: |
|
Actually, still a lot of repetition in for instance in:
But at least the logs are usable.
Maybe it was just me reducing the default count from 5 down to 1: |
This comment was marked as duplicate.
This comment was marked as duplicate.
Someone did it?? |
1 line / ms
This 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.
Originally posted by @marc-hb in #4672 (comment)
cc:
The text was updated successfully, but these errors were encountered: