GNU bug report logs - #55707
syslogd logging kernel messages slowly?

Previous Next

Full log

View this message in rfc822 format

From: Ludovic Courtès <ludo <at> gnu.org>
To: Luis Felipe <luis.felipe.la <at> protonmail.com>
Cc: 55707 <at> debbugs.gnu.org, 55488 <at> debbugs.gnu.org
Subject: bug#55707: syslogd logging kernel messages slowly?
Date: Sat, 04 Jun 2022 21:30:24 +0200

Ludovic Courtès <ludo <at> gnu.org> skribis:

>   2. Explicitly disable syncing for some of the log files by prepending
>      a hyphen right before the file name in syslogd.conf (info
>      "(inetutils) syslogd invocation").

Tried this (in addition to ‘fdatasync’):

--8<---------------cut here---------------start------------->8---
(define %default-syslog.conf
  (plain-file "syslog.conf" "
     # Log all error messages, authentication messages of
     # level notice or higher and anything of level err or
     # higher to the console.
     # Don't log private authentication messages!
     *.alert;auth.notice;authpriv.none      -/dev/console

     # Log anything (except mail) of level info or higher.
     # Don't log private authentication messages!
     *.info;mail.none;authpriv.none          /var/log/messages

     *.=debug                               -/var/log/debug

     # Same, in a different place.
     *.info;mail.none;authpriv.none         -/dev/tty12

     # The authpriv file has restricted access.
     authpriv.*                              /var/log/secure

     # Log all the mail messages in one place.
     mail.*                                 -/var/log/maillog
"))
--8<---------------cut here---------------end--------------->8---

In addition to the hyphens, notice that now only debugging info goes to
/var/log/debug (previously everything going to /var/log/messages would
also go to /var/log/debug, which is kinda silly).

This halves the number of ‘fdatasync’ calls and thus doubles the
throughput, but we’re still spending ~0.1s on ‘fdatasync’ for each line,
which is slow.

So the next solution is to not ‘fdatasync’ on /var/log/messages either:

--8<---------------cut here---------------start------------->8---
(define %default-syslog.conf
  (plain-file "syslog.conf" "
     # Log all error messages, authentication messages of
     # level notice or higher and anything of level err or
     # higher to the console.
     # Don't log private authentication messages!
     *.alert;auth.notice;authpriv.none      -/dev/console

     # Log anything (except mail) of level info or higher.
     # Don't log private authentication messages!
     *.info;mail.none;authpriv.none         -/var/log/messages

     # Log \"debug\"-level entries and nothing else.
     *.=debug                               -/var/log/debug

     # Same, in a different place.
     *.info;mail.none;authpriv.none         -/dev/tty12

     # The authpriv file has restricted access.
     # 'fsync' the file after each line.
     authpriv.*                              /var/log/secure

     # Log all the mail messages in one place.
     mail.*                                 -/var/log/maillog
"))
--8<---------------cut here---------------end--------------->8---

With this, the system boots much more quickly.

I’m tempted to commit the above syslog.conf.  From a look at the code
and doc, it seems that neither rsyslog nor systemd-journald does
anything like “fsync after each logged line”, so the config above sounds
like a reasonable default (at any rate, the current default is
definitely unreasonable on slow spinning disks).

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

Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.