bug#55707: syslogd logging kernel messages slowly?

["Ludovic Courtès" <ludo@gnu.org>]

Hello,

I noticed this weird phenomenon on an x86_64 machine (a 2GHz Celeron),
seen in an excerpt of /var/log/messages:

--8<---------------cut here---------------start------------->8---
May 29 12:34:49 localhost avahi-daemon[349]: avahi-daemon 0.8 starting up.
May 29 12:35:10 localhost vmunix: [    1.391673] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 1
May 29 12:35:10 localhost vmunix: [    1.392751] xhci_hcd 0000:00:14.0: hcc params 0x200077c1 hci version 0x100 quirks 0x0000000000009810
May 29 12:35:10 localhost vmunix: [    1.393050] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.17
May 29 12:35:10 localhost vmunix: [    1.393057] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 29 12:35:10 localhost vmunix: [    1.393062] usb usb1: Product: xHCI Host Controller
May 29 12:35:10 localhost vmunix: [    1.393065] usb usb1: Manufacturer: Linux 5.17.11-gnu xhci-hcd
May 29 12:35:10 localhost vmunix: [    1.393069] usb usb1: SerialNumber: 0000:00:14.0
May 29 12:35:11 localhost vmunix: [    1.393645] hub 1-0:1.0: USB hub found
May 29 12:35:11 localhost vmunix: [    1.393669] hub 1-0:1.0: 6 ports detected
May 29 12:35:11 localhost vmunix: [    1.394524] xhci_hcd 0000:00:14.0: xHCI Host Controller
May 29 12:35:11 localhost vmunix: [    1.394534] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
May 29 12:35:11 localhost vmunix: [    1.394543] xhci_hcd 0000:00:14.0: Host supports USB 3.0 SuperSpeed
May 29 12:35:11 localhost vmunix: [    1.394652] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.17
May 29 12:34:50 localhost elogind[341]: Watching system buttons on /dev/input/event4 (Darfon HP USB Keyboard)
May 29 12:35:11 localhost vmunix: [    1.394659] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
May 29 12:35:11 localhost vmunix: [    1.394664] usb usb2: Product: xHCI Host Controller
May 29 12:35:11 localhost vmunix: [    1.394667] usb usb2: Manufacturer: Linux 5.17.11-gnu xhci-hcd
May 29 12:35:11 localhost vmunix: [    1.394670] usb usb2: SerialNumber: 0000:00:14.0
May 29 12:35:11 localhost vmunix: [    1.395217] hub 2-0:1.0: USB hub found
May 29 12:35:12 localhost vmunix: [    1.395243] hub 2-0:1.0: 1 port detected
May 29 12:35:12 localhost vmunix: [    1.395581] i8042: PNP: No PS/2 controller found.
May 29 12:35:12 localhost vmunix: [    1.395584] i8042: Probing ports directly.
May 29 12:35:12 localhost vmunix: [    1.396141] serio: i8042 KBD port at 0x60,0x64 irq 1
May 29 12:35:12 localhost vmunix: [    1.396153] serio: i8042 AUX port at 0x60,0x64 irq 12
May 29 12:35:12 localhost vmunix: [    1.396481] mousedev: PS/2 mouse device common for all mice
May 29 12:35:12 localhost vmunix: [    1.396980] rtc_cmos 00:00: RTC can wake from S4
May 29 12:35:12 localhost vmunix: [    1.397736] rtc_cmos 00:00: registered as rtc0
May 29 12:35:12 localhost vmunix: [    1.397770] rtc_cmos 00:00: setting system clock to 2022-05-29T10:33:31 UTC (1653820411)
May 29 12:35:13 localhost vmunix: [    1.397817] rtc_cmos 00:00: alarms up to one month, y3k, 242 bytes nvram
May 29 12:35:13 localhost vmunix: [    1.397843] i2c_dev: i2c /dev entries driver
May 29 12:34:52 localhost NetworkManager[339]: <info>  [1653820492.6955] manager[0xfdb000]: monitoring kernel firmware directory '/lib/firmware'.
--8<---------------cut here---------------end--------------->8---

The “vmunix” messages take 3 seconds to get logged, although they
correspond to events that occurred in ~0.5 second before syslogd was
started.

During boot up on that machine, if you go to tty12, where syslogd relays
messages, you can indeed see those lines getting displayed pretty slowly.

Has anyone experienced that?

Thanks,
Ludo’.