Skip to content

Refactor the trace system #2172

Closed
Closed

Description

@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).

Activity

  1. plbossart commented on Dec 5, 2019

    @plbossart
    Member

    @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.

  2. paulstelian97 commented on Dec 5, 2019

    @paulstelian97
    CollaboratorAuthor

    @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.

  3. added
    NotableEnhancement is significant or notable for release.
    on Jan 15, 2020
  4. added this to the v1.6 milestone on Jan 15, 2020
  5. lgirdwood commented on Jan 15, 2020

    @lgirdwood
    Member

    Lets initially pencil in for 1.6

  6. mmaka1 commented on Feb 17, 2020

    @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.

  7. paulstelian97 commented on Feb 17, 2020

    @paulstelian97
    CollaboratorAuthor

    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.

  8. lgirdwood commented on Feb 17, 2020

    @lgirdwood
    Member

    @mmaka1 @paulstelian97 TSC agenda item ?

  9. dbaluta commented on Feb 17, 2020

    @dbaluta
    Collaborator

    @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.

  10. lgirdwood commented on Feb 17, 2020

    @lgirdwood
    Member

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

  11. dbaluta commented on May 6, 2020

    @dbaluta
    Collaborator

    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"
    
  12. lgirdwood commented on Aug 18, 2020

    @lgirdwood
    Member

    This blocked on UUID which has now merged. @ktrzcinx do you think we can merge in next few weeks ?

  13. modified the milestones: v1.6, v1.7 on Sep 1, 2020
  14. lgirdwood commented on Jan 12, 2021

    @lgirdwood
    Member

    All now merged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    NotableEnhancement is significant or notable for release.enhancementNew feature or request

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions