Logger

The sof-logger is used to print logs delivered from the FW dma_trace mechanism by searching log entries in the ldc file (logs dictionary) that are generated by the SMEX (Sof Metadata Extractor) tool. Every entry declared in the FW is placed in an elf output file (e.g. sof-apl) in the .static_log_entries section in a struct form that is defined in sof/src/include/sof/trace.h in the sof fw repo.

The ldc file contains snd_sof_logs_header and snd_sof_uids_header (defined in smex/ldc.h). snd_sof_logs_header is followed by a .static_log_entries section incorporated from the FW elf file (e.g. sof-apl). snd_sof_logs_header contains basic information about the .static_log_entries section such as base_address and data_length. The sof-logger works by reading entry parameters values and entries addresses from the FW dma_trace mechanism and searching for suitable entries in the ldc file by its address. The snd_sof_uids_header struct is followed by the .static_uuid_entries section content from the FW elf file. A single uuid entry is defined in sof/src/include/sof/lib/uuid.h in the sof fw repo.

Logger usage

Usage sof-logger <option(s)> <file(s)>

-h

help

-l ldc_file

Specify the ldc file (debugging information and strings)

-i in_file

Get traces from the in_file instead of from the default “/sys/kernel/debug/sof/etrace”

-o out_file

Specify the output file instead of the default stdout

-t

Get traces from “/sys/kernel/debug/sof/trace” instead of from the default “/sys/kernel/debug/sof/etrace”

-p

Get traces from stdin instead of the default “/sys/kernel/debug/sof/etrace”

-c clock

Set the timestamp clock in MHz

-n

Disable checking the firmware version with the default verification file “/sys/kernel/debug/sof/fw_version”

-v ver_file

Enable checking the firmware version with the ver_file file instead of the default: “/sys/kernel/debug/sof/fw_version”

-s

Take a snapshot of state

-r

Less formatted output for chained log processors

-L

Hide log location in source code

-f precision

Set timestamp precision

-g

Hide timestamp

-d

Dump ldc information

-F filter

Update trace filtering

Examples

  • Gets traces from the “/sys/kernel/debug/sof/etrace” file; disable compatibility check between given ldc_file with fw_version saved in default location and prints logs to stdout

    sof-logger -l ldc_file -n

  • Gets traces from the “/sys/kernel/debug/sof/etrace” file; verifies the fw_version with the ver_file file and prints logs to stdout

    sof-logger -l ldc_file -v ver_file

  • Get traces from the “/sys/kernel/debug/sof/etrace” file and prints logs to stdout

    sof-logger -l ldc_file

  • Get traces from the “/sys/kernel/debug/sof/etrace” file and prints logs to the out_file file

    sof-logger -l ldc_file -o out_file

  • Get traces from the “/sys/kernel/debug/sof/trace” file and prints logs to stdout

    sof-logger -l ldc_file -t

  • Get traces from the “/sys/kernel/debug/sof/trace” file and prints logs to the out_file file

    sof-logger -l ldc_file -t -o out_file

  • Get traces from stdin and prints logs to stdout

    sof-logger -l ldc_file -p

  • Get traces from stdin and prints logs to the out_file file

    sof-logger -l ldc_file -p -o out_file

  • Get traces from the trace_dump file and prints logs to stdout

    sof-logger -l ldc_file -i trace_dump

  • Get traces from the trace_dump file and prints logs to the out_file file

    sof-logger -l ldc_file -i trace_dump -o out_file

  • c flag defines the clock value (in MHz) used to format log timestamps. By default, the clock value is set to 19.2 (MHz). The below example sets the clock value to 19.9 (MHz).

    sof-logger -l ldc_file -i trace_dump -o out_file -c 19.9

  • Dump information from the ldc file (such as the ABI version and the uuid dictionary) to stdout

    sof-logger -l ldc_file -d

Note

debugfs files used by sof-logger:

  • etrace: direct access to the shared TRACE window of the SOF firmware

  • trace: using DMA to stream debug trace information from SOF firmware (on distribution kernels sof_debug=1 module option for snd_sof might be needed if the /sys/kernel/debug/sof/trace file is not present)

Note

If sof-logger is started (or restarted) while firmware is active, the initial trace messages might be incomplete. This can happen as current (as of SOF version 1.9) trace is implemented with a ringbuffer between firmware and the kernel driver. When sof-logger is started, kernel will always start to read the ringbuffer from 0 position, independently of firmware state. If firmware write pointer just wrapped around when sof-logger is started, sof-logger will only show the traces after the wrap. Firmware write position is also reset whenever firmware is booted, including runtime suspend and resume. To capture traces over runtime suspend events, the kernel trace interface will signal end of file at runtime suspend. When sof-logger notices the end of file marker, it will reopen the trace file and start reading from position 0 and thus be in sync with the firmware when it is resumed.

Sometimes error messages about dropped logs are printed. If that is a problem, increasing DMA_TRACE_LOCAL_SIZE in the relevant platform.h file can be helpful.

Trace filtering

Current log levels can be changed for any instance of a component at runtime. To do so, use the -F option and the following argument format:

<log_level>=”<component1>[, <component2>]”

Where <log_level> can be one of the following:

  • c / critical

  • e / error

  • w / warning

  • i / info

  • d / debug

  • v / verbose

After the = character, all components are listed in a comma-separated format. Each component begins with name followed by an optional instance description.

The list of possible component names comes from the UUID declaration. Refer to the UUID API for more detailed information. Use the -d flag in the logger to list component names from the ldc file content.

Example output:

$./sof-logger -d log/sof-cnl.ldc
logger ABI Version is   5:2:0
ldc_file ABI Version is 5:2:0

Components uuid dictionary size:        824 bytes
Components uuid base address:           0x1FFFA000
Components uuid entries:
         ADDRESS                                    UUID NAME
      0x1FFFA000  <8b9d100c-6d78-418f-90a3-e0e805d0852b> host
      0x1FFFA01C  <f11818eb-e92e-4082-82a3-dc54c604ebb3> pipe-task
      0x1FFFA03C  <34dc0385-fc2f-4f7f-82d2-6cee444533e0> volume-task
      0x1FFFA05C  <b77e677e-5ff4-4188-af14-fba8bdbf8682> volume
      0x1FFFA078  <c1c5326d-8390-46b4-aa47-95c3beca6550> src
      0x1FFFA134  <c2b00d27-ffbc-4150-a51a-245c79c5e54b> dai
      -------------------------------------------------- cnt: 6

A special wildcard - * - can be used to apply a given trace level to each component.

Instance descriptions can have one of the following forms:

  • * - each component instance

  • X.* - each component on selected pipeline X

  • X.Y - component on pipeline X with id Y

Trace level changes work in the same order as options given in a command line, and a new set overwrites old values. It allows you to easily enable verbose logs only for selected components and keep the lowest possible log level (critical) for others, as shown in the following example:

sof-logger -l ldc_file -t -Fcritical=* -Fverbose=”dai*, volume1.1”

A similar example may be prepared for components on a particular pipeline:

sof-logger -l ldc_file -t -Fc=* -Fv=*1.*

Verbose and debug log levels

To enable verbose and debug trace messages, select the “Trace->Trace verbose” option in the firmware build menuconfig (in addition to setting the proper log levels as described above).

Disabling DSP power gating

After a firmware reset (such as after power gating in suspend mode) custom filter settings will be lost. Thus consider disabling power gating during your debug session. The way this is done is slightly different on every platform, two examples follow:

  1. Intel PCI based:

sudo su
echo on >/sys/devices/pci0000\:00/0000\:$(lspci -nn | grep "audio contoller" | awk '{print $1;}')/power/control

  1. NXP imx8mp:

sudo su
echo on>/sys/class/devlink/platform:power-domains:audiomix-pd--platform:3b6e8000.dsp/consumer/power/control

To re-enable automatic suspend use echo auto, the current status can be read from the runtime_status file in these sysfs directories.

Trace filtering details

  • The filtering mechanism occurs on the firmware side so, after changing the log level to verbose for each component, the DSP can be overwhelmed by tracing.

  • Core functionality is provided by the DSP, so filtering does not work in offline mode - during conversion in a previously saved input file.

  • The trace filtering affects only traces sent after the filter setup, so traces already stored on the kernel side are not affected. If a certain log level is needed before a filter has been setup the DECLARE_TR_CTX() macro at the beginning of the respective component’s source file can be adapted.

  • Filters are set up incrementally, so when loggers are run twice with different settings, then filters from the first run will not be restored to the default state but will be replaced by a new one. Active trace filters are stored in the firmware runtime memory. To reset the filters to the default state, a firmware reset is needed.

  • Communication between the firmware and logger occurs through the kernel debugfs. The logger writes new trace settings to sys/kernel/debug/sof/filter. These will be used to create IPC messages with new trace levels. A simple text data format is used:

    log1_level uuid1_id pipe1_id comp1_id; [log2_level uuid2_id pipe2_id comp2_id;]\n

    Any unused uuid_id should be set here to 0; other unused fields should be set to -1. log_level must always be set to a valid value that represents LOG_LEVEL_* defined values.