[systemd-devel] What causes "systemd-journald[3256]: Missed 127 kernel messages"

[Ulrich Windl]

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]

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]

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]

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]

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]

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]

(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