bug#55707: syslogd logging kernel messages slowly?

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

bug#55707: syslogd logging kernel messages slowly?

[Luis Felipe via Bug reports for GNU Guix]

[-- Attachment #1.1: Type: text/plain, Size: 1536 bytes --]

Hey,

On Monday, June 6th, 2022 at 10:00, Ludovic Courtès <ludo@gnu.org> wrote:

> > > I’m curious to see if it fixes your other boot-up issues, timeouts and
> > > all, Luis.
> > 

> > Do I simply put both definitions (inetutils/fdatasync and %default-syslog.conf) in my system config and reconfigure...? Because I tried that and nothing seems to change.
> > 

> > Or, once defined, do I have to use inetutils/fdatasync and %default-syslog.conf somewhere in my system packages...?
> 

> Sorry, I wasn’t clear. Let’s forget about ‘inetutils/fdatasync’ because
> it doesn’t have a measurable impact AFAICS.
> 

> In your config file, you first put:
> 

> --8<---------------cut here---------------start------------->8---
> (define %new-default-syslog.conf
> [...]
> --8<---------------cut here---------------end--------------->8---
> 

> 

> Then, you replace ‘%desktop-services’ with:
> 

> --8<---------------cut here---------------start------------->8---
> 

> (modify-services %desktop-services
> (syslog-service-type
> _ => (syslog-configuration
> 

> (config-file %new-default-syslog.conf))))
> --8<---------------cut here---------------end--------------->8---

This does reduce the time it takes to get to GDM log in screen from GRUB. It used to be around 2:35 minutes, but now it takes around 1:25 minutes, which is nice.

Unfortunately, though, I still can't start a GNOME session. I logged in, and stared at a blackish screen for about 5 minutes. Nothing happened :)

[-- Attachment #1.2: publickey - luis.felipe.la@protonmail.com - 0x12DE1598.asc --]
[-- Type: application/pgp-keys, Size: 1815 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 509 bytes --]

bug#55707: syslogd logging kernel messages slowly?

[Ludovic Courtès]

Hi,

Luis Felipe <luis.felipe.la@protonmail.com> skribis:

> This does reduce the time it takes to get to GDM log in screen from GRUB. It used to be around 2:35 minutes, but now it takes around 1:25 minutes, which is nice.

Alright, so commit 264ca9452fae827d6621b28b8972f4b1d68401a1 closes this
particular issue (#55707).

Thanks,
Ludo’.