1

The Linux kernel developers decided by default to ratelimit messages to /dev/kmsg. This was because they did not like the amount of messages written by systemd, particularly when debug is passed on the kernel command line.

systemd exceeds this limit even without enabling debug messages.

[    5.879211] systemd: 18 output lines suppressed due to ratelimiting

This is the only such message in my kernel log (dmesg) at the moment. So I might think it means that only 18 successive lines were lost, ending around t=5.879211. In some sense this would be a fairly limited loss. I probably wouldn't need to worry about it unless I noticed some of the very early boot units (pre-journald) were failing.

So, is that right? Is there a circumstance where this analysis could mislead me?

0

Actually this idea is pretty wrong. Firstly, this message does not necessarily represent a single block of 18 successive systemd messages having been lost. Secondly, you can't tell when /dev/kmsg has been ratelimited if the process still has it open for writing. You only get a message about it once the process closes /dev/kmsg. The message shows a count of all the suppressed lines from that writer.


Each individual writer (file descriptor) to /dev/kmsg gets it's own ratelimit struct. And as part of the initialization...

ratelimit_set_flags(&user->rs, RATELIMIT_MSG_ON_RELEASE);

the ratelimit is set to only log on release. That is, when the file descriptor is closed. For a long-running process, this might be less than helpful... and the init system i.e. systemd definitely counts as a long-running process.

The reason you see this log message, is that systemd from the initrd closes /dev/kmsg before it exec()s systemd from the system's root filesystem.

So the messages lost during the initrd aren't necessarily lost as a block. There could be several different blocks of lost messages, so the log would not be as straightforward to analyze as I had thought.

Also any number of messages could have been lost later on, from the time between exec()ing systemd from the root filesystem, up to the point systemd stops logging to the /dev/kmsg altogether and switches to journald. And indeed they are, which we can see during shutdown (using a console that remains on, like a serial console). When systemd exec()s systemd-shutdown, /dev/kmsg is automatically closed, and we see

[  OK  ] Reached target Final Step.
         Starting Reboot...
[   76.318839] systemd-shutdow: 32 output lines suppressed due to ratelimiting
...

This is all in contrast to certain ratelimited messages from the kernel e.g. kauditd_printk_skb: 32 callbacks suppressed. In this case RATELIMIT_MSG_ON_RELEASE is not used.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.