Refactor the trace system

[paulstelian97]

As per the comments from #2133 (comment) we need to make some major changes to the trace system.

I want to have that discussion moved into a separate issue where we can follow it instead of polluting other trace related changes.

The main issue pointed out there is that traces should be enabled and disabled at runtime instead of
compile time.

@plbossart @akloniex @mmaka1 Let's continue the discussion here so we all know what we should do.

@lgirdwood suggested we should strive to obtain an API similar to trace_err(object, format, ...) where the object will contain the required trace class, object ID and the support for runtime/userspace enable/disable of the traces (ref: #2287 (comment) )

Current work: #2398 (new ABI version -- the new trace interface isn't backward compatible, but we don't want the IPC ABI to be affected because IPC will keep working just fine), #2408 (components will have a pointer to the driver itself), #2410 (UUID for every component type for traces, instead of the linear IDs).

[plbossart]

@paulstelian97 it's not necessarily runtime instead of build-time, it's also useful to use Kconfig to select a config directly so that you don't have to do any real-time configuration. But you can still allow the user to override the default set in Kconfig.
It's quite common for kernel Kconfigs to set a default value for a module parameter, but that parameter can still be overridden by the user.

[paulstelian97]

@paulstelian97 it's not necessarily runtime instead of build-time, it's also useful to use Kconfig to select a config directly so that you don't have to do any real-time configuration. But you can still allow the user to override the default set in Kconfig.
It's quite common for kernel Kconfigs to set a default value for a module parameter, but that parameter can still be overridden by the user.

That I'd still consider runtime, even if you can change defaults at compile time. I need to figure out
how the runtime changes in case something is wanted different from what kconfig does.

[lgirdwood]

Lets initially pencil in for 1.6

[mmaka1]

The existing TRACE_CLASS_ id space does not seem to scale for fw parts that may be independently developed, like components and dais while still seems good enough for parts of the infrastructure. Therefore #2366 reduced trace class level identification of components and dais to single TRACE_CLASS_COMP and TRACE_CLASS_DAI (this one re-used from the dai-component) with a plan to bring back precise identification of components and dais using assigned uuids deployed as parts of the ldc files, so that recompilation of the logger will not be necessary to print out uuids (or nice names) of any new components and dais, potentially compiled separately and loaded dynamically in future with the core fw as part of a platform specific configuration.

Regarding the log filtering, the run-time method could be implemented using the uuids only, so that it would enable precise components and dais log filtering (1), quite important for algorithm and hw dais developers. Then, assigning a single uuid to the infrastructure (fw core) would allow to filter it as well if necessary. Please note that many existing infrastructure traces seem to be verbose dbg information, not real run-time important events and probably should be moved to dbg level. This would reduce amount of info level traces coming from the infrastructure significantly anyway (2).

The most expensive solution would be a run-time configurable trace filter for individual infrastructure parts. However (1) should satisfy those users who develop their algorithms and new dai drivers. (2) could help them to reduce infrastructure output completely when they are focused on their parts if needed. Static compile time dbg/info switching for the infrastructure may be good enough for developers, otherwise filtering may be extended as the ultimate step.

[paulstelian97]

The existing TRACE_CLASS_ id space does not seem to scale for fw parts that may be independently developed, like components and dais while still seems good enough for parts of the infrastructure. Therefore #2366 reduced trace class level identification of components and dais to single TRACE_CLASS_COMP and TRACE_CLASS_DAI (this one re-used from the dai-component) with a plan to bring back precise identification of components and dais using assigned uuids deployed as parts of the ldc files, so that recompilation of the logger will not be necessary to print out uuids (or nice names) of any new components and dais, potentially compiled separately and loaded dynamically in future with the core fw as part of a platform specific configuration.

Regarding the log filtering, the run-time method could be implemented using the uuids only, so that it would enable precise components and dais log filtering (1), quite important for algorithm and hw dais developers. Then, assigning a single uuid to the infrastructure (fw core) would allow to filter it as well if necessary. Please note that many existing infrastructure traces seem to be verbose dbg information, not real run-time important events and probably should be moved to dbg level. This would reduce amount of info level traces coming from the infrastructure significantly anyway (2).

The most expensive solution would be a run-time configurable trace filter for individual infrastructure parts. However (1) should satisfy those users who develop their algorithms and new dai drivers. (2) could help them to reduce infrastructure output completely when they are focused on their parts if needed. Static compile time dbg/info switching for the infrastructure may be good enough for developers, otherwise filtering may be extended as the ultimate step.

I'd argue that, for the purpose of bug reporting, a more fine tuned runtime filtering might be necessary. That's what I got from Pierre. The flow would be: bug reported, we'd ask for a specific runtime configuration and a reproduction, unless the bug has very low reproducibility we'd get the specific logs so we could focus on fixing the specific issue itself. Perhaps runtime filtering can be done at the debug log level alone?

Otherwise I agree. UUIDs should be the way to go. We would introduce UUIDs in general with IPC 2.0 as well, for the actual IPC and configurability. Tuning whether some logs appear always vs which should only appear when debugging is an important feature. But some debug logs are extremely verbose (I remember the WFE/WFX logs) so tuning out some while allowing others may be useful.

We should also be aware in case of crashes that DMA trace may stop working. In that case we only have the etrace mechanism, which could contain only errors but sometimes it's not the errors themselves that are useful. In that case we would enable TRACE_MBOX, but if we cannot do runtime tuning of which traces appear, the mailbox will be spammed by mostly irrelevant traces related to other very verbose components. That's why I'm still pushing for that runtime configurability.

[lgirdwood]

@mmaka1 @paulstelian97 TSC agenda item ?

[dbaluta]

@lgirdwood added it. I will invite @paulstelian97 to TSC meeting if he can join and also if there are no objections. Anyway, I know the general idea.

[lgirdwood]

@mmaka1 please also attend and present the ECL plugins if they are ready.

[dbaluta]

Copying here a message from @lgirdwood

 Ithink 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

    Trace should be runtime configurable
    Trace should be configurable per component / subsystem.
    Trace should have several levels like Linux printk(LEVEL),

This would allow us to do things like

Enable all trace upto level 4 in MUX1.1 component

echo "MUX1.1 level=4" > /sysfs/kernel/debug/sof/trace_events

or enable all trace events for debug features 1,3 and 8 in KWD 1.0

echo "KWD1.0 debug=1,3,8" > /sysfs/kernel/debug/sof/trace_events"