End-user documentation and bug reporting

[fxthomas]

I'm not sure if this is the correct place for documentation requests, feel free to point me to the right place.

I had a rather difficult time finding SOF firmware logs with the official kernel from my distribution when trying to debug thesofproject/sof#3868. One of the reasons is that it is still not clear to me, as an end-user relatively unfamiliar with SOF/kernel development, exactly how to get logs in a reliable way in either my own or my distribution's kernel builds.

The questions below are things I'm wondering or found out while doing research.

---

What's the difference between trace and etrace?

The documentation on the Logger mentions the existence of two files, /sys/kernel/debug/sof/trace and /sys/kernel/debug/sof/etrace.

• What are they?
• Why two of them?

Since there are two options, and my distro's official kernel only has etrace enabled by default, my hypothesis is that trace has more overhead/is more detailed, and as such is not enabled in default builds. Am I correct?

How to enable log tracing?

By default on my distro's official build etrace is empty and trace doesn't exist, but in custom builds I do following the build instructions both show messages.

• What kernel compilation options control them? Should I need only CONFIG_SND_SOC_SOF_DEBUG and CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE?
• Can I enable them dynamically without having to recompile my distro's official kernel?

What is dynamic debug, is that different from the logger?

This page suggests to use dynamic debug options. Should I expect to get different kinds of information than from the logger (other than the fact that the logs go into the dmesg output instead of a separate tool)?

[paulstelian97]

I'll give my two cents since I know a bit about the logger.

So, trace is so-called DMA trace. The sof-logger tool will block on it until the firmware gives more logs, then will decode (by using the .ldc file associated with the running firmware, which you must manually provide in the command currently) those logs from the binary format to a user-readable format.

etrace is the mailbox tracing mechanism. It's a bit more reliable (if the firmware hangs we may be unable to fetch the last few log entries via the regular DMA trace mechanism, but they will be visible in the mailbox trace), but harder to read since it's a circular buffer and the logger tool will not really know where the cursor is, currently, so you will see newer logs before older ones at times. The tool just reads it and decodes it in bulk, and if you want updates you re-run it. It's only intended for debugging issues that break the regular logger.

The firmware itself needs to have logs enabled (the default settings only log errors AFAIK).

Dynamic debug fine tunes what kernel messages will show up in dmesg or not. As far as I know (I may be wrong) it doesn't affect the firmware logger messages.

[lgirdwood]

Thanks @fxthomas, we are working on this, I think all the developers know the debug tooling so this was missed when we looked at the docs.

[fxthomas]

@paulstelian97 Thank you, that clears a lot of my questions already!

The firmware itself needs to have logs enabled (the default settings only log errors AFAIK).

Do I absolutely need to recompile it to do that, or can I enable more verbose logs at run- or boot-time?

On my custom builds where I'm able to properly get logs, the messages themselves (not their order) in trace and etrace are different (trace (with the -t option) has a ton of messages where etrace only has a few warnings), is the difference in verbosity expected?

@lgirdwood Great! We've all written docs that omit some "obvious" stuff that is absolutely not obvious at all, I know I'm guilty of it too. Looking forward to the updates.

[paulstelian97]

On my custom builds where I'm able to properly get logs, the messages themselves (not their order) in trace and etrace are different (etrace has a ton of messages where trace only has a few warnings), is the difference in verbosity expected?

With most configurations of the firmware (including the default one), yes, there is an expected difference in verbosity, though I believe not in the way you describe it. If you recompile the firmware with a custom configuration that enables Trace error (default on) and Trace mailbox (default off, will send more messages to etrace buffer) you should see they're pretty similar over time.

With DMA trace you should start the logger, then try to use the firmware (e.g. aplay) and see the logs in real time as they are produced. With etrace you cannot do that.

[fxthomas]

Okay, that explains a bit more, and I can indeed see the logs in real time with DMA trace on my custom kernel. Thanks!

(Just noticed that I mixed up the two in my earlier messages; /sys/kernel/debug/sof/etrace (mailbox) is the one that's always present but empty in the official kernels, and /sys/kernel/debug/sof/trace (DMA) is only present in my custom builds. Edited to reflect the correct name.)

[fxthomas]

Just want to add that I just discovered how to enable DMA trace in official builds!

I should have discovered much earlier than I did — the mention of being able to enable firmware trace "dynamically by setting flags in the SOF core module parameter" in SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE led me to find out commit 2ab4c50f6955514150.

Adding /etc/modprobe.d/sof-debug.conf with the following line did the trick and lets sof-logger use both DMA and mailbox traces in the official kernel just like in my custom kernel:

options snd_sof sof_debug=1

[ujfalusi]

@fxthomas, can you take a look at pull request #351? It adds the missing information (I hope) you have pointed out.

[marc-hb]

shameless plug: thesofproject/sof-test#666 check-sof-logger: rewrite most of it so it can actually find bugs

[fxthomas]

@ujfalusi Thanks, that looks good to me, it'll be a good way to get started for future bug reports!