bug#55707: bug#55488: GDM, GNOME: Can't start desktop session after upgrade

[Ludovic Courtès]

Hi,

Ludovic Courtès <ludo@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@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@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@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@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’.