Why rpmsg_tty messages are logged into the journal log?

Technical Support
, ,
1

I have an application running on Torizon OS 6 which implements rpmsg communication between Torizon OS and M7.
The communication itself works, but I noticed some CPU usage from systemd-journald process (~7%).
I run journalctl command to see the logs and I see all the messages received from M7.
I don’t see the messages sent by Torizon OS.
Her is a snippet of the log

Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb6f 63 6b 5c 22 2c 5c 22 74 79 70 65 5c 22 3a 5c  ock\",\"type\":\
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb22 69 6e 70 75 74 5c 22 2c 5c 22 76 61 6c 75 65  "input\",\"value
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb5c 22 3a 74 72 75 65 2c 5c 22 66 61 75 6c 74 43  \":true,\"faultC
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb6f 64 65 5c 22 3a 30 7d 2c 7b 5c 22 69 6f 5c 22  ode\":0},{\"io\"
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb3a 5c 22 6d 61 67 6e 65 74 69 63 5f 62 72 61 6b  :\"magnetic_brak
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb65 5c 22 2c 5c 22 74 79 70 65 5c 22 3a 5c 22 6f  e\",\"type\":\"o
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb75 74 70 75 74 5c 22 2c 5c 22 76 61 6c 75 65 5c  utput\",\"value\
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb22 3a 66 61 6c 73 65 2c 5c 22 66 61 75 6c 74 43  ":false,\"faultC
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb6f 64 65 5c 22 3a 30 7d 2c 7b 5c 22 69 6f 5c 22  ode\":0},{\"io\"
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb3a 5c 22 74 79 72 65 5f 6c 69 67 68 74 5c 22 2c  :\"tyre_light\",
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb5c 22 74 79 70 65 5c 22 3a 5c 22 6f 75 74 70 75  \"type\":\"outpu
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb74 5c 22 2c 5c 22 76 61 6c 75 65 5c 22 3a 66 61  t\",\"value\":fa
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb6c 73 65 2c 5c 22 66 61 75 6c 74 43 6f 64 65 5c  lse,\"faultCode\
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb22 3a 30 7d 5d 22 7d 0a                          ":0}]"}.
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb5b 5d 0a                                         [].
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb7b 22 74 79 70 65 22 3a 22 63 68 75 6e 6b 22 2c  {"type":"chunk",
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb22 6d 73 67 49 64 22 3a 31 31 39 32 38 2c 22 73  "msgId":11928,"s
Jul 19 13:12:35 verdin-imx8mp-15128331 kernel: rpmsg_tty_cb65 6e 64 65 72 22 3a 22 6d 2d 63 6f 72 65 22 2c  ender":"m-core",

I don’t think that these messages should be logged into the journal log. This waste resources and increases eMMC wear.
Is there a way to disable the logging of rpmsg messages?

2

Hi, I’m the Toradex AI Assistant. I’m in early beta, and I would appreciate your feedback.
The Toradex Support team will follow up with you shortly!

Did you like my answer?

:+1: :-1:

Hello,

To address the issue of rpmsg messages being logged into the journal log on Torizon OS, you can take the following steps to disable or control the verbosity of these logs. The messages you’re seeing are kernel log messages, and their logging behavior can be adjusted through the kernel’s dynamic debug feature or by configuring the log level.

  1. Dynamic Debug: Linux kernel’s dynamic debug feature allows you to control how much logging is output by different kernel modules. You can disable logging for the rpmsg module by echoing a command to the dynamic debug control file. For example:

    echo 'file drivers/rpmsg/* +p' > /sys/kernel/debug/dynamic_debug/control

    This command disables logging for all files in the drivers/rpmsg directory. Note that the path might vary based on the kernel version and configuration. You might need to adjust the path according to your setup.

  2. Kernel Log Level: You can also control the verbosity of the kernel log messages by setting the log level. The kernel log level can be set at boot time via the kernel command line or at runtime using the dmesg command. To reduce the verbosity to only show warnings and more critical messages, you can do:

    • At boot time, add loglevel=4 to the kernel command line parameters.
    • At runtime, execute dmesg -n 4.

    This sets the log level to 4, which corresponds to warnings. Messages with a higher log level (numerically lower) will be shown, but debug and informational messages will be suppressed.

  3. Systemd-journald Configuration: While the above methods control the kernel’s logging behavior, systemd-journald also has configurations that can affect logging. You can adjust the SystemMaxUse and RuntimeMaxUse parameters in /etc/systemd/journald.conf to limit the amount of disk and RAM used for logs, respectively. However, this does not directly stop rpmsg messages from being logged but can help manage the resource usage.

Please note, adjusting logging levels and disabling specific logs should be done with caution, as it may hinder your ability to diagnose issues in the future. Always ensure that you have an alternative means of capturing necessary logs, especially when debugging system issues.

Best regards,
Toradex AI Assistant

Please, also check if these links can help you solve your problem:

Running FreeRTOS on the Cortex-M4 of a Colibri iMX7 | Toradex Developer Center.

3

Hi @vix !

Specifically on the memory wear here.

By default, Torizon OS doesn’t have persistent storage for jounald. After rebooting the module you can see that the messages from the previous boot won’t be there anymore.
Related:

Quickly looking at the imx_rpmsg_tty’s source code, seems like such messages come from this print_hex_dump:

https://git.toradex.com/cgit/linux-toradex.git/tree/drivers/rpmsg/imx_rpmsg_tty.c?h=toradex_5.15-2.2.x-imx#n44

With that information, I ask you to try the @ToradexAI’s approaches regarding controlling the logged messages.

If you are going to test the Dynamic Debug approach, please refer to its documentation, as the exact command shared by @ToradexAI might be misleading: Dynamic debug — The Linux Kernel documentation

And, of course you can also modify the driver so it will never print any messages. But you might want to keep the messages there for a future debugging case :wink:

Best regards,

4

Hi @henrique.tx
thank you very much for your answer.
I agree that probably the best option is to leverage on Dynamic Debug approach.
I read the documentation you linked and here is what I learned/understood:

  • /proc/dynamic_debug/control exists, and so kernel of Torizon OS has Dynamic Debug - good :grin:
  • head /proc/dynamic_debug/control shows the currently configured behaviour, and the items I see are all related to net/bluetooth/bnep/core.c

If I would like disabling debug logging for module imx_rpmsg_tty I should run the following command

echo "module imx_rpmsg_tty -p" > /proc/dynamic_debug/control

But nothing changes and I get all the debug messages in journalctl.
From the documentation you linked I read that I can specify the Dynamic Debug while loading the module, and in Torizon OS I load it using /etc/modules-load.d as suggested by @jeremias.tx here.
Should I load it using /etc/modprobe.d so that I can specify more advanced options?

5

Hi @vix !

After more carefully reading the Dynamic Debug documentation, I saw this:

For print_hex_dump_debug() and print_hex_dump_bytes(), only the p flag has meaning, other flags are ignored.

Looking at imx_rpmsg_tty, it uses print_hex_dump (with KERN_DEBUG) instead of print_hex_dump_debug (imx_rpmsg_tty.c « rpmsg « drivers - linux-toradex.git - Linux kernel for Apalis, Colibri and Verdin modules):

	print_hex_dump(KERN_DEBUG, __func__, DUMP_PREFIX_NONE, 16, 1,
			data, len,  true);

In the header include/linux/printk.h (printk.h « linux « include - linux-toradex.git - Linux kernel for Apalis, Colibri and Verdin modules) we can understand a bit better the relation between print_hex_dump and print_hex_dump_debug:

  • If defined(CONFIG_DYNAMIC_DEBUG) || (defined(CONFIG_DYNAMIC_DEBUG_CORE) && defined(DYNAMIC_DEBUG_MODULE)) is true (A), then print_hex_dump_debug will be defined as dynamic_hex_dump, which I guess this is the thing that makes us able to control dynamic debug.

  • Otherwise (elif), if defined(DEBUG) is true (B), then print_hex_dump_debug will simply be print_hex_dump with KERN_DEBUG.

So, since (A) will be true (and (B) won’t be evaluated), and print_hex_dump_debug is not used by the this driver, I guess that controlling the log using dynamic debug won’t be possible.

But I think that setting the log level will still have effect:

https://www.kernel.org/doc/html/latest/core-api/printk-basics.html

Be aware that I didn’t tested nor tried anything by myself. While you keep trying on your side, I will try to get someone’s time to review this message :slight_smile:

Best regards,

6

Hi @henrique.tx,
thanks a lot!.

I’ve talked to NXP tech support and they agree that print_hex_dump_debug() should be used inside imx_rpmsg_tty.c instead of print_hex_dump(KERN_DEBUG, ...).
I’ve opened this PR on github but I think that Toradex can patch in this way its own fork of the repo.

Let me know your position on this suggestion.

7

Hi @vix !

I am checking internally if/how we can take this forward.

Btw, have you tested you patch? Does it work as expected?

Best regards,

8

Honestly speaking… I haven’t.
Based on my knowledge, build a Yocto recipe is not a task that I feel under muy control.
This is one of the most important reasons why I decided to go with an out-of-the-box OS like Torizon OS.