[BUG] Issues with using Zephyr CONFIG_LOG_MIPI_SYST_USE_CATALOG with SOF

[kv2019i]

Describe the bug
Currently SOF Zephyr builds use "TEXT" logging output by default.

One alternative to text logging is the MIPI SYS-T Catalog logging backend which is found in Zephyr upstream:
zephyrproject-rtos/zephyr#19841
https://docs.zephyrproject.org/latest/samples/subsys/logging/syst/README.html

There are currently some issues enabling this build with SOF:

• Builds with Cadence xtensa tool chain fail with MIPI_SYST_USE_CATALOG (work/zephyr/lib/os/cbprintf_packaged.c:22:2: error: "CONFIG_CBPRINTF_PACKAGE_SUPPORT_TAGGED_ARGUMENT) -> toolchain: xtensa: enable C11 features with xt-clang zephyrproject-rtos/zephyr#58499
• No logs from SOF emitted to backend (is_in_log_strings_section() check always returns false for SOF prints, potential issue in linker scripts) -> logs dropped with CONFIG_LOG_MIPI_SYST_USE_CATALOG=y zephyrproject-rtos/zephyr#58476 , fix in logging: fix format strings not being put in log_strings_area zephyrproject-rtos/zephyr#58719
• Builds MIPI SYST USE_CAT and xt-clang will fail due to missing libc functionality (memset, strlen, ... ) -> west.yml: update Zephyr to 3.4.99 #7836 and modules: mipi-syst: support minimal C library zephyrproject-rtos/zephyr#59287
• FW panic if USE_CATALOG=y on MTL -> [BUG] IPC timeout with CONFIG_LOG_MIPI_SYST_USE_CATALOG=y #7839

To Reproduce
Add following to work/sof/app/prj.conf

CONFIG_LOG_BACKEND_ADSP_MTRACE=y
CONFIG_LOG_BACKEND_ADSP_MTRACE_OUTPUT_SYST=y
CONFIG_LOG_MIPI_SYST_ENABLE=y
CONFIG_LOG_MIPI_SYST_USE_CATALOG=n

And rebuild SOF. Capture log with "mtrace-reader.py" to a file "dsplog.bin" and post-process with upstream mipi-syst tools like:

systprint -c ../../work/build-tgl/zephyr/mipi_syst_collateral.xml dsplog.bin

Reproduction Rate
100%

Expected behavior
Sys-T Catalog logging can be enabled for all support logging backends.

Impact
Inability to use more effiecient standard dictionary format.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: n/a
   • SOF: e7fc334
   • Zephyr: 7d54586751cfe405d2cdcfd850f8100bc9844f63
2. Name of the topology file
   • Topology: n/a
3. Name of the platform(s) on which the bug is observed.
   • Platform: Intel MTL

Screenshots or console output

[kv2019i]

FYI @abonislawski @marc-hb @dbaluta @nashif @lgirdwood @mwasko

[kv2019i]

Hmm, interesting, I tried SYS_USE_CATALOG with SOF2.5 (uses 9ff0732 , Zephyr ~3.3 e3ae110a05d3427647a03fcbeff4478c195c5a48 and Zephyr SDK 0.15), and SYST_USE_CATALOG works with that combination. So this is potentially a regression on Zephyr side (I see no changes on SOF side). FYI @dcpleung

[dcpleung]

Maybe it's due to

commit caea9dc1966588de0a6ea712cb388d237acbfa83
Author: Kumar Gala <kumar.gala@intel.com>
Date:   Thu Mar 16 05:55:18 2023 +0000

    logging: Use TYPE_SECTION macros for log strings
    
    Clean up log_strings to utilize macros for handling sections.
    
    Signed-off-by: Kumar Gala <kumar.gala@intel.com>

[kv2019i]

Tested reverting the "logging: Use TYPE_SECTION macros" , but did not seem to help. Filed a bug now to Zephyr side for better tracking. I'll try to bisect better when I just have the chance.

[dcpleung]

Any instructions on how to reproduce it on hardware? I have a UPX11 to test on. Meanwhile, I will try running Sys-T under QEMU to see if I can reproduce it using Zephyr's sample app.

[kv2019i]

@dcpleung
Basicly you need to rebuild SOF for tgl with following:

+++ b/app/prj.conf
@@ -25,6 +25,14 @@ CONFIG_LOG_BUFFER_SIZE=4096
 # Use stack that is sufficient for SOF backends
 CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=4096
 
+CONFIG_LOG_BACKEND_ADSP_MTRACE=y
+CONFIG_LOG_BACKEND_ADSP_MTRACE_OUTPUT_SYST=y
+CONFIG_LOG_MIPI_SYST_ENABLE=y
+CONFIG_LOG_MIPI_SYST_USE_CATALOG=y

On UP i11, you will have to install the binary to IPC4 location and enable IPC4 in kernel. See instructions (to install SOF2.5 release on TGL systems) at :
https://github.com/thesofproject/sof-bin/tree/main/v2.5.x

The syst logs should come out with (https://github.com/thesofproject/sof/blob/main/tools/mtrace/mtrace-reader.py)
sh> sudo mtrace-reader.py

For debugging, I additionally set "CONFIG_LOG_PRINTK=n" in work/sof/app/prj.conf and use the cavstool.py to observe the printk output.

I'm also trying to reproduce with the Zephyr unit test for syst. I got the unit test built for TGL UP i11 -- I got it to run but test never completes and there was no output. So I might have hit the same bug, or some user-error on my part.

[kv2019i]

Progress on both issues. One is a regression and another is missing definition in xt-clang toolchain setup ( zephyrproject-rtos/zephyr#58499 ). USE_CATALOG does require full libc support, and now one more issue is hit when using xt-clang is that the libc implemntation provided with xt-clang is not complete and build fails to link errors:

/home/kvehmane/xtensa/XtDevTools/install/tools/RI-2022.10-linux/XtensaTools/bin/xtensa-elf-ld: zephyr/libzephyr.a(cbprintf_packaged.c.obj):(.literal.cbvprintf_package+0x2c): undefined reference to `strlen'
/home/kvehmane/xtensa/XtDevTools/install/tools/RI-2022.10-linux/XtensaTools/bin/xtensa-elf-ld: zephyr/libzephyr.a(cbprintf_packaged.c.obj):(.literal.cbvprintf_package+0x34): undefined reference to `memcpy'
/home/kvehmane/xtensa/XtDevTools/install/tools/RI-2022.10-linux/XtensaTools/bin/xtensa-elf-ld: zephyr/libzephyr.a(cbprintf_packaged.c.obj): in function `cbvprintf_package':
/home/kvehmane/pr-ssd/f33-zephyrsof/work/zephyr/lib/os/cbprintf_packaged.c:675: undefined reference to `strlen'
/home/kvehmane/xtensa/XtDevTools/install/tools/RI-2022.10-linux/XtensaTools/bin/xtensa-elf-ld: /home/kvehmane/pr-ssd/f33-zephyrsof/work/zephyr/lib/os/

[kv2019i]

We now have at least RFC level solutions for all issues. Using these, I did a quick comparison of the code size impact of enabling MIPI_SYST_USE_CATALOG logging (SYST_CAT). Following is a Intel MTL build with xt-clang toolchain default params from SOF main:

• Runtime performance: ~ around same cost to calling context
• Overall image size: 810 KiB (SYST-CAT) versus 867 KiB (TEXT), difference of -57 KiB
• Example sections with notable differences
  - .text -> 317 KiB vs 385 KiB, difference of -68 KiB
  - .rodata -> 317 KiB vs 360 KiB, difference of -43 KiB
  - .log_strings -> 55 KiB vs 0 KiB, difference of +55KiB

This is with zephyrproject-rtos/zephyr#58757 that allows to use minimal libc with mipi-syst-lib.

[kv2019i]

One issue solved (ability to use mipi-syst library with minimal libc now possible with Zephyr mainline).

Unfortunately a new issue found on MTL where DSP crashes when catalog feature is enabled -> #7839

[kv2019i]

I'm happy to report the last blocking bug has been solved in mainline (just did a retest today), so we can close this.

[kv2019i]

FYI @dcpleung finally it all works! :)