Hi,
Ludovic Courtès skribis:
> Here’s another debugging trick; would be great if you could try this:
>
> (define strace-syslogd
> (program-file "strace-syslogd"
> #~(apply execl #$(file-append strace "/bin/strace")
> "strace" ;argv[0]
> "-f" "-Tt" "-o" "/syslogd.log" "-s" "80"
> #$(file-append inetutils "/libexec/syslogd")
> (cdr (command-line)
>
>
> and then:
>
> (modify-services %desktop-services
> (syslog-service-type
>_ => (syslog-configuration
> (syslogd strace-syslogd
>
> This creates a log file, /syslogd.log, which will allow us to see the
> time it takes syslogd to read from /proc/kmsg and hopefully to determine
> the origin of delays.
I tried this on a machine I have access to that exhibits this slowness,
and here’s what I get (excerpt that spans 2+ seconds of syslogd
activity):
--8<---cut here---start->8---
328 18:46:13 openat(AT_FDCWD, "/dev/console", O_WRONLY|O_CREAT|O_APPEND,
0644) = 4 <0.99>
328 18:46:13 openat(AT_FDCWD, "/var/log/messages", O_WRONLY|O_CREAT|O_APPEND,
0644) = 5 <0.75>
328 18:46:13 ioctl(5, TCGETS, 0x7ffe23d6c930) = -1 ENOTTY (Inappropriate
ioctl for device) <0.000261>
328 18:46:13 openat(AT_FDCWD, "/var/log/debug", O_WRONLY|O_CREAT|O_APPEND,
0644) = 6 <0.000201>
328 18:46:13 ioctl(6, TCGETS, 0x7ffe23d6c930) = -1 ENOTTY (Inappropriate
ioctl for device) <0.000138>
328 18:46:13 openat(AT_FDCWD, "/dev/tty12", O_WRONLY|O_CREAT|O_APPEND, 0644)
= 7 <0.001059>
328 18:46:13 ioctl(7, TCGETS, {B38400 opost isig icanon echo ...}) = 0
<0.000101>
328 18:46:13 openat(AT_FDCWD, "/var/log/secure", O_WRONLY|O_CREAT|O_APPEND,
0644) = 8 <0.77>
328 18:46:13 ioctl(8, TCGETS, 0x7ffe23d6c930) = -1 ENOTTY (Inappropriate
ioctl for device) <0.39>
328 18:46:13 openat(AT_FDCWD, "/var/log/maillog", O_WRONLY|O_CREAT|O_APPEND,
0644) = 9 <0.70>
[…]
328 18:46:13 read(3, "<5>[0.00] Linux version 5.17.11-gnu (guix@guix)
(gcc (GCC) 10.3.0, GNU l"..., 1024) = 981 <0.83>
328 18:46:13 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.59>
322 18:46:13 +++ exited with 0 +++
328 18:46:13 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444,
st_size=2962, ...}, 0) = 0 <0.49>
328 18:46:13 writev(7, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Linux version 5.17.11-gnu (guix@guix) (gcc
(GCC) 10.3.0, "..., iov_len=124}, {iov_base="\r\n", iov_len=2}], 6) = 152
<0.86>
328 18:46:13 fsync(7) = -1 EINVAL (Invalid argument)
<0.36>
328 18:46:13 writev(6, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Linux version 5.17.11-gnu (guix@guix) (gcc
(GCC) 10.3.0, "..., iov_len=124}, {iov_base="\n", iov_len=1}], 6) = 151
<0.63>
328 18:46:13 fsync(6) = 0 <0.380857>
328 18:46:13 writev(5, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Linux version 5.17.11-gnu (guix@guix) (gcc
(GCC) 10.3.0, "..., iov_len=124}, {iov_base="\n", iov_len=1}], 6) = 151
<0.79>
328 18:46:13 fsync(5) = 0 <0.131763>
328 18:46:13 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000213>
328 18:46:13 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000160>
328 18:46:13 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444,
st_size=2962, ...}, 0) = 0 <0.49>
328 18:46:13 writev(7, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Command line:
BOOT_IMAGE=/gnu/store/w8py29cnikbg69jvxhxb3"..., iov_len=314},
{iov_base="\r\n", iov_len=2}], 6) = 342 <0.000123>
328 18:46:13 fsync(7) = -1 EINVAL (Invalid argument)
<0.40>
328 18:46:13 writev(6, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Command line:
BOOT_IMAGE=/gnu/store/w8py29cnikbg69jvxhxb3"..., iov_len=314}, {iov_base="\n",
iov_len=1}], 6) = 341 <0.74>
328 18:46:13 fsync(6) = 0 <0.23>
328 18:46:13 writev(5, [{iov_base="Jun 4 18:46:13", iov_len=15}, {iov_base="
", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1},
{iov_base="vmunix: [0.00] Command line:
BOOT_IMAGE=/gnu/store/w8py29cnikbg69jvxhxb3"..., iov_len=314}, {iov_base="\n",
iov_len=1}], 6) = 341 <0.000156>
328 18:46:13 fsync(5) = 0 <0.099143>
328 18:46:14 r
