[BUG] Issues with using Zephyr CONFIG_LOG_MIPI_SYST_USE_CATALOG with SOF

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

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

Screenshots or console output

@abonislawski

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

@dcpleung

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

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>

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.

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.

@dcpleung

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

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/

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.

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

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

@dcpleung

FYI @dcpleung finally it all works! :)

Navigation Menu

Repository navigation

[BUG] Issues with using Zephyr CONFIG_LOG_MIPI_SYST_USE_CATALOG with SOF #7703

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] Issues with using Zephyr CONFIG_LOG_MIPI_SYST_USE_CATALOG with SOF #7703

Description

Activity

kv2019i commented on May 29, 2023

kv2019i commented on May 29, 2023

dcpleung commented on May 30, 2023

kv2019i commented on May 31, 2023

dcpleung commented on May 31, 2023

kv2019i commented on May 31, 2023

kv2019i commented on May 31, 2023

kv2019i commented on Jun 1, 2023

kv2019i commented on Jun 20, 2023

kv2019i commented on Sep 5, 2023

kv2019i commented on Sep 5, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions