Hi Florian,

"pelzflorian (Florian Pelz)" <pelzflorian@pelzflorian.de> skribis:

> On Tue, Apr 14, 2020 at 11:40:53AM +0200, pelzflorian (Florian Pelz) wrote:
>> On Tue, Apr 14, 2020 at 11:03:55AM +0200, Ludovic Courtès wrote:
>> > To confirm this hypothesis, we need to run “strace -t”, see below (sorry
>> > for not thinking about doing it!).  If you can try again with the patch
>> > below, that’s awesome.  Then we’ll compare the timestamps in
>> > /var/log/messages and those in the strace log.
>> 
>> Will do.  I will only send /var/log/messages and /dbus.* traces then.
>> 
>
> Logs are attached.

Woow, the first dbus-daemon process needs 20s from exec to PID file:

--8<---------------cut here---------------start------------->8---
13:46:06 execve("/gnu/store/nlb24nrrrkn2h9vflnqigcf2hx58rvyx-dbus-1.12.16/bin/dbus-daemon", ["/gnu/store/nlb24nrrrkn2h9vflnqigcf2hx58rvyx-dbus-1.12.16/bin/dbus-daemon", "--nofork", "--system", "--syslog-only"], 0x7ffc94ca62c8 /* 1 var */) = 0
[…]
13:46:14 openat(AT_FDCWD, "/gnu/store/vclzrvbxac8ipc8g1ncq5gjjj8gdvxw3-connman-1.38/etc/dbus-1/system.d", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
13:46:16 fstat(4, {st_mode=S_IFDIR|0555, st_size=2048, ...}) = 0
[…]
13:46:19 openat(AT_FDCWD, "/gnu/store/mw57n9nj3y20bfm9ijcbpm16gpsik6sg-polkit-0.116/etc/dbus-1/system.d", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
13:46:21 fstat(4, {st_mode=S_IFDIR|0555, st_size=2048, ...}) = 0
[…]
13:46:21 bind(4, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
[…]
13:46:26 openat(AT_FDCWD, "/var/run/dbus/pid", O_WRONLY|O_CREAT|O_EXCL, 0644) = 5
13:46:26 fcntl(5, F_GETFL)              = 0x8001 (flags O_WRONLY|O_LARGEFILE)
13:46:26 fstat(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
13:46:26 write(5, "212\n", 4)           = 4
13:46:26 close(5)                       = 0
--8<---------------cut here---------------end--------------->8---

Some of the openat(2) calls take no less than 2s (probably due to DVD
seek time + decompression time).

In parallel we see:

--8<---------------cut here---------------start------------->8---
Apr 14 13:46:08 localhost shepherd[1]: Service dbus-system could not be started. 
Apr 14 13:46:08 localhost shepherd[1]: Service networking depends on dbus-system. 
--8<---------------cut here---------------end--------------->8---

This happens 2s after exec, meaning that it already took 3s to go from
“start dbus” to “process forked + exec’d”.

Could you build an ISO image with the patch below on top of
bd4c345ef7ddf3542662fe0872b06393b414a3fc and confirm that it works for
you?  Run:

  ./pre-inst-env guix system disk-image \
     --file-system-type=iso9660 gnu/system/install.scm

Thanks,
Ludo’.