Skip to content

Conversation

@plbossart
Copy link
Member

Add the 'total_data_processed' to the logs to get a better sense of when xruns happen with no space to copy to/from dma buffers, e.g.

[00:01:10.379,758] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 0 available samples: 0, free_samples: 768
[00:01:10.446,761] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 192, free_samples: 0
[00:01:10.447,761] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.448,756] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.449,756] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.450,756] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.451,756] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.452,843] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.453,756] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy, hd->total_data_processed 49664 available samples: 384, free_samples: 0
[00:01:10.453,788] <wrn> dai_comp: comp:0 0x40000 dai_zephyr_copy(): nothing to copy, dd->total_data_processed 55808

The first log is probably ok, this means the DMA has not started yet, but the second one shows the flows are broken with the DMA stuck for a while

plbossart added 3 commits June 2, 2023 11:33
We can skip two code blocks that are completely useless when the
number of samples is exactly zero, and return earlier.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
A 'nothing to copy' log is not really useful without additional
information on when this problem occurred, i.e. if this is on a 1ms
tick or after a longer time.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
This is helpful to see when 'dma_copy_bytes' is zero, e.g.

[00:01:10.446,761] <inf> host_comp: host_get_copy_bytes_normal: comp:1 0x40002 no bytes to copy,
hd->total_data_processed 49664 available samples: 192, free_samples: 0

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Copy link
Collaborator

@kv2019i kv2019i left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure about the first change. The glitch warnings have been useful.

copy_bytes + free_bytes < dd->period_bytes)
comp_warn(dev, "dai_zephyr_copy(): Copy_bytes %d + free bytes %d < period bytes %d, possible glitch",
copy_bytes, free_bytes, dd->period_bytes);

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, we do skip the glitch detection as well. This has no functional impact, but will affect debugging as the buffer avail/free state is not printed out when we do run out.

/* return if nothing to copy */
if (!samples) {
comp_warn(dev, "dai_zephyr_copy(): nothing to copy");
comp_warn(dev, "dai_zephyr_copy(): nothing to copy, dd->total_data_processed %llu", dd->total_data_processed);
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Welcome addition. Might be good to add also data on the sink/src_samples status, providing hints whether we are not copying because of pipeline not providing/consuming data, or because of the DAI side. But can be done in later PR.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

on the contrary, I would suggest add less characters as possible, if there is an error here, we already get the information, we can add more information personally in local build, add too much debug related code will eventually make 1.9MB exhausted, then have to split out modules as loadable modules, then maybe more bugs will come.

@lgirdwood
Copy link
Member

@plbossart Build error on host fuzzer

odules/sof/CMakeFiles/modules_sof.dir/home/runner/work/sof/sof/workspace/sof/src/audio/host-zephyr.c.obj -MF modules/sof/CMakeFiles/modules_sof.dir/home/runner/work/sof/sof/workspace/sof/src/audio/host-zephyr.c.obj.d -o modules/sof/CMakeFiles/modules_sof.dir/home/runner/work/sof/sof/workspace/sof/src/audio/host-zephyr.c.obj -c /home/runner/work/sof/sof/workspace/sof/src/audio/host-zephyr.c
/home/runner/work/sof/sof/workspace/sof/src/audio/host-zephyr.c:425:3: error: array size is negative
                comp_info(dev, "no bytes to copy, hd->total_data_processed %llu available samples: %d, free_samples: %d",
                ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/home/runner/work/sof/sof/workspace/sof/src/include/sof/audio/component.h:238:2: note: expanded from macro 'comp_info'
        trace_dev_info(trace_comp_get_tr_ctx, trace_comp_get_id,        \
        ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/home/runner/work/sof/sof/workspace/sof/zephyr/include/sof/trace/../../../../src/include/sof/trace/trace.h:431:2: note: expanded from macro 'trace_dev_info'
        trace_event_with_ids(_TRACE_INV_CLASS, get_ctx_m(dev),          \
        ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/home/runner/work/sof/sof/workspace/sof/zephyr/include/sof/trace/../../../../src/include/sof/trace/trace.h:160:2: note: expanded from macro 'trace_event_with_ids'
        _trace_event_with_ids(LOG_LEVEL_INFO, class, ctx, id_1, id_2,   \
        ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
note: (skipping 22 expansions in backtrace; use -fmacro-backtrace-limit=0 to see all)
/home/runner/work/sof/sof/workspace/sof/src/include/sof/trace/preproc-private.h:122:63: note: expanded from macro '_META_REQRS_2'
#define _META_REQRS_2(...)    _META_REQRS_1(  _META_REQRS_1  (__VA_ARGS__))
                              ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~^~~~~~~~~~~~~
/home/runner/work/sof/sof/workspace/sof/src/include/sof/trace/preproc-private.h:123:28: note: expanded from macro '_META_REQRS_1'
#define _META_REQRS_1(...) __VA_ARGS__
                           ^
/home/runner/work/sof/sof/workspace/sof/src/include/sof/trace/preproc-private.h:123:28: note: expanded from macro '_META_REQRS_1'
#define _META_REQRS_1(...) __VA_ARGS__
                           ^~~~~~~~~~~
1 error generated.

@plbossart
Copy link
Member Author

I can't recall what this 1+ yr old PR was about, closing

@plbossart plbossart closed this Aug 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

9 participants