Package: guix;
Reported by: Ludovic Courtès <ludo <at> gnu.org>
Date: Sun, 29 May 2022 15:00:02 UTC
Severity: normal
Done: Ludovic Courtès <ludo <at> gnu.org>
Bug is archived. No further changes may be made.
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: bug#55488: GDM, GNOME: Can't start desktop session after upgrade Date: Sat, 04 Jun 2022 19:07:20 +0200
Hi,
Ludovic Courtès <ludo <at> gnu.org> 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.000099>
328 18:46:13 openat(AT_FDCWD, "/var/log/messages", O_WRONLY|O_CREAT|O_APPEND, 0644) = 5 <0.000075>
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.000077>
328 18:46:13 ioctl(8, TCGETS, 0x7ffe23d6c930) = -1 ENOTTY (Inappropriate ioctl for device) <0.000039>
328 18:46:13 openat(AT_FDCWD, "/var/log/maillog", O_WRONLY|O_CREAT|O_APPEND, 0644) = 9 <0.000070>
[…]
328 18:46:13 read(3, "<5>[ 0.000000] Linux version 5.17.11-gnu (guix <at> guix) (gcc (GCC) 10.3.0, GNU l"..., 1024) = 981 <0.000083>
328 18:46:13 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000059>
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.000049>
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.000000] Linux version 5.17.11-gnu (guix <at> guix) (gcc (GCC) 10.3.0, "..., iov_len=124}, {iov_base="\r\n", iov_len=2}], 6) = 152 <0.000086>
328 18:46:13 fsync(7) = -1 EINVAL (Invalid argument) <0.000036>
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.000000] Linux version 5.17.11-gnu (guix <at> guix) (gcc (GCC) 10.3.0, "..., iov_len=124}, {iov_base="\n", iov_len=1}], 6) = 151 <0.000063>
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.000000] Linux version 5.17.11-gnu (guix <at> guix) (gcc (GCC) 10.3.0, "..., iov_len=124}, {iov_base="\n", iov_len=1}], 6) = 151 <0.000079>
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.000049>
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.000000] 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.000040>
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.000000] Command line: BOOT_IMAGE=/gnu/store/w8py29cnikbg69jvxhxb3"..., iov_len=314}, {iov_base="\n", iov_len=1}], 6) = 341 <0.000074>
328 18:46:13 fsync(6) = 0 <0.239999>
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.000000] 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 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000128>
328 18:46:14 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000180>
328 18:46:14 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000100>
328 18:46:14 writev(7, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] KERNEL supported cpus:", iov_len=45}, {iov_base="\r\n", iov_len=2}], 6) = 73 <0.000189>
328 18:46:14 fsync(7) = -1 EINVAL (Invalid argument) <0.000039>
328 18:46:14 writev(6, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] KERNEL supported cpus:", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000097>
328 18:46:14 fsync(6) = 0 <0.198157>
328 18:46:14 writev(5, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] KERNEL supported cpus:", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000284>
328 18:46:14 fsync(5) = 0 <0.098527>
328 18:46:14 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000136>
328 18:46:14 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000133>
328 18:46:14 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000488>
328 18:46:14 writev(7, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Intel GenuineIntel", iov_len=43}, {iov_base="\r\n", iov_len=2}], 6) = 71 <0.000213>
328 18:46:14 fsync(7) = -1 EINVAL (Invalid argument) <0.000141>
328 18:46:14 writev(6, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Intel GenuineIntel", iov_len=43}, {iov_base="\n", iov_len=1}], 6) = 70 <0.000219>
328 18:46:14 fsync(6) = 0 <0.096564>
328 18:46:14 writev(5, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Intel GenuineIntel", iov_len=43}, {iov_base="\n", iov_len=1}], 6) = 70 <0.000215>
328 18:46:14 fsync(5) = 0 <0.125492>
328 18:46:14 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000128>
328 18:46:14 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000130>
328 18:46:14 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000252>
328 18:46:14 writev(7, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] AMD AuthenticAMD", iov_len=41}, {iov_base="\r\n", iov_len=2}], 6) = 69 <0.000368>
328 18:46:14 fsync(7) = -1 EINVAL (Invalid argument) <0.000130>
328 18:46:14 writev(6, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] AMD AuthenticAMD", iov_len=41}, {iov_base="\n", iov_len=1}], 6) = 68 <0.000402>
328 18:46:14 fsync(6) = 0 <0.112798>
328 18:46:14 writev(5, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] AMD AuthenticAMD", iov_len=41}, {iov_base="\n", iov_len=1}], 6) = 68 <0.000199>
328 18:46:14 fsync(5) = 0 <0.098952>
328 18:46:14 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000244>
328 18:46:14 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000128>
328 18:46:14 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000252>
328 18:46:14 writev(7, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Hygon HygonGenuine", iov_len=43}, {iov_base="\r\n", iov_len=2}], 6) = 71 <0.000375>
328 18:46:14 fsync(7) = -1 EINVAL (Invalid argument) <0.000039>
328 18:46:14 writev(6, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Hygon HygonGenuine", iov_len=43}, {iov_base="\n", iov_len=1}], 6) = 70 <0.000099>
328 18:46:14 fsync(6) = 0 <0.113492>
328 18:46:14 writev(5, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Hygon HygonGenuine", iov_len=43}, {iov_base="\n", iov_len=1}], 6) = 70 <0.000998>
328 18:46:14 fsync(5) = 0 <0.106071>
328 18:46:15 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000220>
328 18:46:15 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000115>
328 18:46:15 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000115>
328 18:46:15 writev(7, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Centaur CentaurHauls", iov_len=45}, {iov_base="\r\n", iov_len=2}], 6) = 73 <0.000262>
328 18:46:15 fsync(7) = -1 EINVAL (Invalid argument) <0.000048>
328 18:46:15 writev(6, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Centaur CentaurHauls", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000076>
328 18:46:15 fsync(6) = 0 <0.080533>
328 18:46:15 writev(5, [{iov_base="Jun 4 18:46:14", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] Centaur CentaurHauls", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000198>
328 18:46:15 fsync(5) = 0 <0.107653>
328 18:46:15 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000051>
328 18:46:15 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000055>
328 18:46:15 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000093>
328 18:46:15 writev(7, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] zhaoxin Shanghai ", iov_len=45}, {iov_base="\r\n", iov_len=2}], 6) = 73 <0.000197>
328 18:46:15 fsync(7) = -1 EINVAL (Invalid argument) <0.000042>
328 18:46:15 writev(6, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] zhaoxin Shanghai ", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000123>
328 18:46:15 fsync(6) = 0 <0.123659>
328 18:46:15 writev(5, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] zhaoxin Shanghai ", iov_len=45}, {iov_base="\n", iov_len=1}], 6) = 72 <0.000370>
328 18:46:15 fsync(5) = 0 <0.098383>
328 18:46:15 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000138>
328 18:46:15 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000128>
328 18:46:15 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000254>
328 18:46:15 writev(7, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] x86/fpu: x87 FPU will use FXSAVE", iov_len=55}, {iov_base="\r\n", iov_len=2}], 6) = 83 <0.000383>
328 18:46:15 fsync(7) = -1 EINVAL (Invalid argument) <0.000135>
328 18:46:15 writev(6, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] x86/fpu: x87 FPU will use FXSAVE", iov_len=55}, {iov_base="\n", iov_len=1}], 6) = 82 <0.000209>
328 18:46:15 fsync(6) = 0 <0.122001>
328 18:46:15 writev(5, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] x86/fpu: x87 FPU will use FXSAVE", iov_len=55}, {iov_base="\n", iov_len=1}], 6) = 82 <0.000197>
328 18:46:15 fsync(5) = 0 <0.123772>
328 18:46:15 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000102>
328 18:46:15 rt_sigprocmask(SIG_BLOCK, [HUP ALRM], [], 8) = 0 <0.000140>
328 18:46:15 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0444, st_size=2962, ...}, 0) = 0 <0.000167>
328 18:46:15 writev(7, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] signal: max sigframe size: 1440", iov_len=54}, {iov_base="\r\n", iov_len=2}], 6) = 82 <0.000273>
328 18:46:15 fsync(7) = -1 EINVAL (Invalid argument) <0.000129>
328 18:46:15 writev(6, [{iov_base="Jun 4 18:46:15", iov_len=15}, {iov_base=" ", iov_len=1}, {iov_base="localhost", iov_len=9}, {iov_base=" ", iov_len=1}, {iov_base="vmunix: [ 0.000000] signal: max sigframe size: 1440", iov_len=54}, {iov_base="\n", iov_len=1}], 6) = 81 <0.000099>
328 18:46:15 fsync(6) = 0 <0.121488>
--8<---------------cut here---------------end--------------->8---
During that time span, syslogd makes no less than 19 ‘fsync’ calls (not
counting the EINVAL ones), each of which takes between 100ms and
400ms—no wonder it’s slow. (This machine has a low-grade spinning HDD.)
There are two things we can do:
1. Use ‘fdatasync’ rather than ‘fsync’;
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").
I’ll give that a try and report back.
Ludo’.
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.