trace: Add Kconfig options to enable verbose tracing only from certain classes #2133
Conversation
akloniex
requested review from
lbetlej,
lgirdwood,
plbossart,
singalsu and
xiulipan
as code owners
akloniex
force-pushed
the
trace-verbosity-overhaul
branch
from
0ebfb6c to
fc90550
Compare
src/include/sof/trace/trace.h
Outdated
There was a problem hiding this comment.
Pass-by coding style corrections should be separate commits I think?
src/trace/Kconfig
Outdated
There was a problem hiding this comment.
@paulstelian97
I personally don't feel the need for submenu, especially, since these depend on TRACEV, they don't clutter the menu, until user decides to enable TRACEV, at which point these options appear instantly, allowing user to pick trace classes to enable.
There was a problem hiding this comment.
@akloniex Can you surround them with if TRACEV & endif # TRACEV ?
There was a problem hiding this comment.
If applies depends and there is no need to repeat it on every entry
paulstelian97
left a comment
paulstelian97
left a comment
There was a problem hiding this comment.
Interesting idea and indeed I felt the need for something like this as well. But I feel the implementation is slightly hard to digest, check the comments on what I find slightly confusing. I'm not willing to block this though.
lgirdwood
left a comment
lgirdwood
left a comment
There was a problem hiding this comment.
We should be able to trim this down a bit when we have trace levels similar to linux.
|
@akloniex can you report on CI |
akloniex
force-pushed
the
trace-verbosity-overhaul
branch
2 times, most recently
from
3c4280a to
d0df7a8
Compare
|
SOFCI TEST |
akloniex
force-pushed
the
trace-verbosity-overhaul
branch
from
d0df7a8 to
7fc52b9
Compare
akloniex
force-pushed
the
trace-verbosity-overhaul
branch
from
7fc52b9 to
4629310
Compare
…n classes Currently, after enabling TRACEV via Kconfig, message log is flooded with various messages, most of which do not help to debug specific issues, due to vast volume of messages sent. This patch adds Kconfig options for each TRACE_CLASS, to enable logs from this class specifically. Signed-off-by: ArturX Kloniecki <arturx.kloniecki@linux.intel.com>
akloniex
force-pushed
the
trace-verbosity-overhaul
branch
from
4629310 to
7761724
Compare
| #define trace_asrc_with_ids(comp_ptr, __e, ...) \ | ||
| trace_event_comp(TRACE_CLASS_SRC, comp_ptr, \ | ||
| __e, ##__VA_ARGS__) | ||
| trace_event_comp(SRC, comp_ptr, __e, ##__VA_ARGS__) |
There was a problem hiding this comment.
Sorry, but I'm actually not in favour of this change (and others like this throughout the patch. The reasons are very simple: (1) it makes it more difficult to grep for these symbols, e.g. if you want to find all uses of TRACE_CLASS_SRC you won't find this any more. Also it makes following symbols in editors more difficult. (2) it makes it look different from the surrounding lines, e.g. the line above, which uses TRACE_CLASS_SRC in full.
If (1) is a trade-off - you win code compactness but you lose clarity, I think (2) is really not good - either convert all of them, or leave them all as is, don't mix them.
There was a problem hiding this comment.
Using "TRACE_CLASS_SRC" directly will not work correctly as that will be expanded to a number and will break the very idea of this PR, to disable verbose traces for particular classes. Maybe TRACE_CLASS_SRC with some prefix or suffix?
There was a problem hiding this comment.
@lyakh It was already picked up by @paulstelian97 and explained on other occurence of this change, here: #2133 (comment)
The intermediate macro trace_event_comp, causes premature TRACE_CLASS_* token expansion, which could be solved by quite some dirty work under the hood in trace_event macro family expansions, or (in my opinion) more elegantly, here.
One could argue that greping for TRACE_CLASS_* doesn't make much sense anymore, as we've already wrapped (almost, reaching 100% soon) all traces in their respective trace_* macros.
If you have an idea how to solve token pasting and expansion more elegantly, I'm open for suggestions, but I honestly think that this route is cleaner than appending _ to tokens to prevent their expansion, and then additionally accounting for it in trace-verbose-private.h.
There was a problem hiding this comment.
@paulstelian97 thanks for the explanation, I see now. But now my question is then: is it really worth it? Is it really worth adding all those levels of macros if we anyway have the trace-verbose-private.h header, which has a bunch of defines for each of the CONFIG_TRACE_VERBOSE_* options? Wouldn't it be much easier and compact to just add
#if CONFIG_TRACE_VERBOSE_xxx
#define trace_asrc_with_ids(comp_ptr, __e, ...) ...
#else
#define trace_asrc_with_ids(...) do {} while (0)
#endif
in every affected file? Most of them would then just involve changing a couple of lines at the top, others, calling generic macros directly from the code, like dai.c, without wrapping them, will need such a define added at the top, which would (arguably) also simplify them?
There was a problem hiding this comment.
@lyakh Tbh if we're doing that I'd say having the definition for trace_asrc_with_ids and every other such macro in a common header and make those macros public would be an easy way out. That sure is a large redo of this change and everyone would thus have to use these custom functions instead of the raw trace_event functions to benefit from that disabling.
Also in case we go with that, use the UNUSED macro instead of a do-while-0 loop. It was built specifically for using in disabled traces.
There was a problem hiding this comment.
@paulstelian97 I'd be fine keeping those defines in respective .c as long as they're used only there. I don't see a need for a common header if all or at least most of them are only used in a single file. However, if sufficiently many of them are or can be used in multiple files, then yes, we could use a common header.
|
@akloniex do I get this right that when the traces are disabled they are compiled out? If yes, I am worried about Heisenbugs due to the memory layout change and timing changes. it'd be more interesting to jump to the trace and do nothing, which would also help move to dynamic debug at some point where the decision is based on a variable set at runtime instead of a constant set at build time. It's really a difference between removing traces and filtering their output selectively. if no, then this is fine. |
|
@plbossart When traces are disabled they are compiled out even without this pull request. This PR only serves to allow more granularity in which of the verbose (analog to DEBUG prints on the kernel side) traces are enabled and which are not. I do see where you're coming from with the actual tracing code but the traces are supposed to be lightweight. The trace classes are not bits for easy comparison of which are enabled and which are not, and doing 34 comparisons per trace will get real expensive real fast (enough so it is no longer worth it to have this hack of a trace system even -- might as well have the messages themselves) Buffer updates trigger a trace update. And I think on my simple use case with only one playback pipeline I can get the etrace buffer full in 3-4 miliseconds (thank Goodness I now have DMA trace so I don't have to worry about losing messages now!). If you also did 34 equality comparisons for each of these traces, you'd suddenly end up spending like double the time per pipeline. |
well, maybe 34 types of traces isn't very smart in the first place... when you need to support a product where e.g. the firmware is released and signed or part of a larger package, it's a logistical nightmare to re-distribute a new firmware just so that the developers can request more or fewer traces in bug reports. You really want to use the released firmware and still gather as much information as possible. If the traces are only intended for developers that can recompile firmware at will, then we'd be writing off an important source of information to help with remote debug. I personally spend more time for the latter category these days. |
I see your point. Then guess I'm asking @lgirdwood for feedback on whether I should pursue Although I'd argue that there are some extremely verbose traces that may still be guarded by a |
@mmaka1 can you chime in as well? I vaguely recall we discussed this notion of 'dynamic debug' some 18-months ago. I am not going to lay on the tracks on this specific PR, but that's an important topic. Note that btw I have the same concern on the kernel side. we tend to enable way too many logs, it's either errors only or a ton of stuff that is not really important. It'd like finer granularity as done for DRM/i915 where you can set some bits on which logs you care about. |
|
SOFCI TEST |
|
I think we've all had some discussion on this topic lately, the key points I can see is granularity (improve SNR) and runtime configuration (no need for debuggers to resign code). I think we have agreement on several features
This would allow us to do things like Enable all trace upto level 4 in MUX1.1 component or enable all trace events for debug features 1,3 and 8 in KWD 1.0 |
7 participants
Currently, after enabling TRACEV via Kconfig, message log is flooded
with various messages, most of which do not help to debug specific
issues, due to vast volume of messages sent. This patch adds Kconfig
options for each TRACE_CLASS, to enable logs from this class specifically.
Signed-off-by: ArturX Kloniecki arturx.kloniecki@linux.intel.com
As next step in trace verbosity overhaul, I would like to take advantage of this feature, and degrade many of trace messages (e.g. reporting function entry) to Verbose level, which would reduce noise in production logs, lower used bandwidth, while still providing developers the possibility to cleanly enable certain log classes for debugging purposes.