bug#55707: syslogd logging kernel messages slowly?

[Ludovic Courtès]

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’.