Discussion:
What causes "systemd-journald[3256]: Missed 127 kernel messages"
Add Reply
Ulrich Windl
2021-06-01 10:42:41 UTC
Reply
Permalink
Hi!

Debugging an issue (a few hundred processes hanging) I used "echo w >/proc/sysrq-trigger". When viewing the journal I found out that it's incomplete, saying (grep Missed):
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 3990 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 252 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 117 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 127 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 126 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 252 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 124 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 373 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 125 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 125 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 126 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 127 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 127 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 121 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 255 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 124 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 250 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 124 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 125 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 121 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 122 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 123 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 125 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 124 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 132 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 257 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 253 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 132 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 128 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 135 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 139 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 138 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 139 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 413 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 138 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 195 kernel messages

A few questions:
1) What causes this?
2) How can systemd know how many messasges were missed?
3) Can I avoid that problem?

(systemd-234-24.82.1.x86_64 of SLES 15 SP2)

Regards,
Ulrich
Reindl Harald
2021-06-01 10:45:29 UTC
Reply
Permalink
Post by Ulrich Windl
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 139 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 413 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 138 kernel messages
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 195 kernel messages
1) What causes this?
2) How can systemd know how many messasges were missed?
3) Can I avoid that problem?
(systemd-234-24.82.1.x86_64 of SLES 15 SP2)
https://serverfault.com/questions/947556/systemd-journal-rate-limit
Ulrich Windl
2021-06-01 11:31:35 UTC
Reply
Permalink
Sorry, once again I forgot to include the list in the reply...
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 139 kernel messages
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 413 kernel messages
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 134 kernel messages
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 138 kernel messages
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 195 kernel messages
1) What causes this?
2) How can systemd know how many messasges were missed?
3) Can I avoid that problem?
(systemd‑234‑24.82.1.x86_64 of SLES 15 SP2)
https://serverfault.com/questions/947556/systemd‑journal‑rate‑limit
Yes, nice hint for those who know the answer (a similar question is there,
but it has no answer).
_______________________________________________
systemd‑devel mailing list
https://lists.freedesktop.org/mailman/listinfo/systemd‑devel
Lennart Poettering
2021-06-01 11:39:32 UTC
Reply
Permalink
Post by Ulrich Windl
Jun 01 12:33:10 h18 systemd-journald[3256]: Missed 195 kernel messages
1) What causes this?
Dunno. Something is massively flooding the kernel log buffer. Probably
some borked driver or so. "dmesg" might tell you what.
Post by Ulrich Windl
2) How can systemd know how many messasges were missed?
Kernel messages delivered to userspace come with a sequence number. If
there are some missing we know the kernel dropped them from the kmsg
log buffer before we could read them.
Post by Ulrich Windl
3) Can I avoid that problem?
Figure out which kernel driver/subsystem is responsible.

You could also enlarge the kernel log buffer, see log_buf_mem= kernel
cmdline switch.

Lennart

--
Lennart Poettering, Berlin
Ulrich Windl
2021-06-01 12:33:26 UTC
Reply
Permalink
in
Post by Lennart Poettering
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 195 kernel messages
1) What causes this?
Dunno. Something is massively flooding the kernel log buffer. Probably
some borked driver or so. "dmesg" might tell you what.
I had meant the dropping of messages, not the creation of such. It seems it's
intentional.
Post by Lennart Poettering
2) How can systemd know how many messasges were missed?
Kernel messages delivered to userspace come with a sequence number. If
there are some missing we know the kernel dropped them from the kmsg
log buffer before we could read them.
OK!
Post by Lennart Poettering
3) Can I avoid that problem?
Figure out which kernel driver/subsystem is responsible.
You could also enlarge the kernel log buffer, see log_buf_mem= kernel
cmdline switch.
Confused: So is it the kjernel dropping/loosing messages, or is it journald?
Post by Lennart Poettering
Lennart
‑‑
Lennart Poettering, Berlin
Lennart Poettering
2021-06-01 12:43:30 UTC
Reply
Permalink
Post by Ulrich Windl
in
Post by Lennart Poettering
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 195 kernel messages
1) What causes this?
Dunno. Something is massively flooding the kernel log buffer. Probably
some borked driver or so. "dmesg" might tell you what.
I had meant the dropping of messages, not the creation of such. It seems it's
intentional.
Ahumm. It does not. Generating such high frequency log messages is a
bug. Please report to your kernel maintainers.
Post by Ulrich Windl
Post by Lennart Poettering
You could also enlarge the kernel log buffer, see log_buf_mem= kernel
cmdline switch.
Confused: So is it the kjernel dropping/loosing messages, or is it journald?
The kernel is generating them faster than userspace can keep up with them.

Lennart

--
Lennart Poettering, Berlin
Ulrich Windl
2021-06-01 12:58:35 UTC
Reply
Permalink
(forgot the list)
14:57
14:43 in
Post by Lennart Poettering
Post by Ulrich Windl
in
On Di, 01.06.21 12:42, Ulrich Windl
Jun 01 12:33:10 h18 systemd‑journald[3256]: Missed 195 kernel messages
1) What causes this?
Dunno. Something is massively flooding the kernel log buffer. Probably
some borked driver or so. "dmesg" might tell you what.
I had meant the dropping of messages, not the creation of such. It seems
it's
Post by Ulrich Windl
intentional.
Ahumm. It does not. Generating such high frequency log messages is a
bug. Please report to your kernel maintainers.
OK, maybe read again the beginning of my message: I had >500 processes in
"D" state when doing "echo w >/proc/sysrq-trigger".
Post by Lennart Poettering
Post by Ulrich Windl
You could also enlarge the kernel log buffer, see log_buf_mem= kernel
cmdline switch.
Confused: So is it the kernel dropping/loosing messages, or is it
journald?
Post by Lennart Poettering
The kernel is generating them faster than userspace can keep up with
them.
That's bad.
Post by Lennart Poettering
Lennart
--
Lennart Poettering, Berlin
Loading...