Improve systemd-timesyncd start-up time

[paulmenzel]

Submission type

• Bug report
• Request for enhancement (RFE)

NOTE: Do not submit anything other than bug reports or RFEs via the issue tracker!

systemd version the issue has been seen with

systemd 232

NOTE: Do not submit bug reports about anything but the two most recently released systemd versions upstream!

Used distribution

Debian Sid/unstable

With 132 ms systemd-timesyncd takes up most of the time to the network.target.

$ systemd --version
systemd 232
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN
$ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @576ms
└─multi-user.target @576ms
  └─libvirt-guests.service @568ms +7ms
    └─libvirtd.service @448ms +119ms
      └─network.target @445ms
        └─NetworkManager.service @379ms +65ms
          └─dbus.service @343ms
            └─basic.target @324ms
              └─sockets.target @324ms
                └─virtlogd.socket @324ms
                  └─sysinit.target @323ms
                    └─systemd-timesyncd.service @190ms +132ms
                      └─systemd-tmpfiles-setup.service @179ms +9ms
                        └─systemd-journal-flush.service @170ms +7ms
                          └─systemd-journald.service @105ms +64ms
                            └─syslog.socket @104ms
                              └─-.mount @90ms
                                └─system.slice @101ms
                                  └─-.slice @90ms
$ journalctl -b -u systemd-timesyncd -o short-precise -b
-- Logs begin at Wed 2017-01-04 16:26:23 CET, end at Thu 2017-01-05 11:52:56 CET. --
Jan 05 11:50:54.658300 xps13 systemd[1]: Starting Network Time Synchronization...
Jan 05 11:50:54.747972 xps13 systemd[1]: Started Network Time Synchronization.
Jan 05 11:51:25.216545 xps13 systemd-timesyncd[278]: Synchronized to time server 193.99.165.217:123 (2.debian.pool.ntp.org).

It’d be great, if the time could be reduced to around 50 ms, if it’s possible.

[poettering]

uh, systemd-timesyncd doesn't do much until it signals complete initialization: it just resolves the systemd-timesync user/group, then reads the timestamp of /var/lib/systemd/clock and bumps the clock accordingly, and that's it.

Nothing of this is time consuming really, except maybe if your NSS is slow, but in that case there's nothing to fix in timesyncd here either...

Note that the criticical chain stuff might be misleading, as it simply shows the slowest path, but this really doesn't mean the units in the chain are really at fault, as they might simply be waiting for IO or IPC or so, and that that's slow might be caused by other components. It's hence only useful as a tool for giving a hint, but it's not sensible for actual profiling.

I will close this now, as there's nothing really here we could fix. we are happy of course to optimize the startup code paths if there is something to do, but the code as it looks here is trivial enough already...

Sorry!

[paulmenzel]

I am open for suggestions for instrumentation/benchmarking/profiling.

Here is a trace for a 175 millisecond startup.
timesyncd-startup.txt

[paulmenzel]

Here is the log with absolute time stamps, where systemd-analyze blame shows it took 104 ms.
timesyncd-startup.txt

[paulmenzel]

The strace time stamps don’t match the 104 ms, if I am not mistaken.

286   15:12:06.713695 execve("/lib/systemd/systemd-timesyncd", ["/lib/systemd/systemd-timesyncd"], [/* 8 vars */]) = 0
286   15:12:06.718624 brk(NULL)         = 0x55f64845e000
286   15:12:06.718664 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
286   15:12:06.718704 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f994d155000
286   15:12:06.718733 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
286   15:12:06.718761 open("/lib/systemd/tls/x86_64/libsystemd-shared-232.so", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
286   15:12:06.718785 stat("/lib/systemd/tls/x86_64", 0x7ffff5055c80) = -1 ENOENT (No such file or directory)
286   15:12:06.718807 open("/lib/systemd/tls/libsystemd-shared-232.so", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
286   15:12:06.718827 stat("/lib/systemd/tls", 0x7ffff5055c80) = -1 ENOENT (No such file or directory)
286   15:12:06.718848 open("/lib/systemd/x86_64/libsystemd-shared-232.so", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
286   15:12:06.718869 stat("/lib/systemd/x86_64", 0x7ffff5055c80) = -1 ENOENT (No such file or directory)
286   15:12:06.718889 open("/lib/systemd/libsystemd-shared-232.so", O_RDONLY|O_CLOEXEC) = 3
286   15:12:06.718911 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\0\0\0\0\0\0\0@\0\0\0\0\0\0\0\0\214!\0\0\0\0\0\0\0\0\0@\0008\0\t\0@\0\"\0!\0\6\0\0\0\4\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\0\0\0@\0\0\0\0\
0\0\0\370\1\0\0\0\0\0\0\370\1\0\0\0\0\0\0\10\0\0\0\0\0\0\0\1\0\0\0\5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\340\30\0\0\0\0\0\20\340\30\0\0\0\0\0\0\20\0\0\0\0\0\0\1\0\0\0\6\0\0\0`\345\30\0\0\0\0
\0`\365\30\0\0\0\0\0`\365\30\0\0\0\0\0\360\244\10\0\0\0\0\0P\260\10\0\0\0\0\0\0\20\0\0\0\0\0\0\2\0\0\0\6\0\0\0\220D!\0\0\0\0\0\220T!\0\0\0\0\0\220T!\0\0\0\0\0\320\2\0\0\0\0\0\0\320\2\0\0\0\0\0\0\10\0\0\0\0\0\0\0
\4\0\0\0\4\0\0\0008\2\0\0\0\0\0\0008\2\0\0\0\0\0\0008\2\0\0\0\0\0\0$\0\0\0\0\0\0\0$\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0P\345td\4\0\0\0\264\202\30\0\0\0\0\0\264\202\30\0\0\0\0\0\264\202\30\0\0\0\0\0\\]\0\0\0\0\0\0\\]\0
\0\0\0\0\0\4\0\0\0\0\0\0\0Q\345td\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\7\0\0\0\4\0\0\0`\345\30\0\0\0\0\0`\365\30\0\0\0\0\0`\365\30\0\0\0\0\0\30
\0\0\0\0\0\0\0\250\0\0\0\0\0\0\0\10\0\0\0\0\0\0\0R\345td\6\0\0\0`\345\30\0\0\0\0\0`\365\30\0\0\0\0\0`\365\30\0\0\0\0\0\240\232\10\0\0\0\0\0\240\232\10\0\0\0\0\0 \0\0\0\0\0\0\0\4\0\0\0\24\0\0\0\3\0\0\0GNU\0\16\37
3\233\4o\346\252\324\213!?&\221\371\f+\35Nk\r\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0H\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0c\0\0\0\22\0\
0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0l\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0s\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0z\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\202\0\0\0\22\0\0\0\0\0\0\0\0\0\
0\0\0\0\0\0\0\0\0\0\234\0\0\0\22\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\253\0\0\0\22\0\0\0", 832) = 832
286   15:12:06.718941 fstat(3, {st_mode=S_IFREG|0644, st_size=2200704, ...}) = 0
286   15:12:06.718964 mmap(NULL, 2205104, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f994cd1b000
286   15:12:06.718985 mmap(0x7f994ceaa000, 569344, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x18e000) = 0x7f994ceaa000
286   15:12:06.719010 mmap(0x7f994cf35000, 1456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f994cf35000
286   15:12:06.719034 close(3)          = 0
286   15:12:06.719059 open("/lib/systemd/libm.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
286   15:12:06.719086 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
286   15:12:06.719109 fstat(3, {st_mode=S_IFREG|0644, st_size=160516, ...}) = 0
286   15:12:06.719130 mmap(NULL, 160516, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f994d12d000
286   15:12:06.719150 close(3)          = 0
286   15:12:06.719170 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
286   15:12:06.719196 open("/lib/x86_64-linux-gnu/libm.so.6", O_RDONLY|O_CLOEXEC) = 3
[…]
286   15:12:06.733388 inotify_init1(IN_NONBLOCK|IN_CLOEXEC) = 11
286   15:12:06.733404 inotify_add_watch(11, 0x7f994ce4d6a0, IN_MOVED_TO|IN_DELETE) = 1
[…]

[paulmenzel]

In #systemd@irc.freenode.net I was told to manually add debugging print statements. I added those to systemd 232 in Debian Sid/unstable.

int main(int argc, char *argv[]) {
        _cleanup_(manager_freep) Manager *m = NULL;
        const char *user = "systemd-timesync";
        uid_t uid;
        gid_t gid;
        int r;

        log_set_target(LOG_TARGET_AUTO);
        log_info("After log_set_target");
        log_set_facility(LOG_CRON);
        log_info("After log_set_facility");
        log_parse_environment();
        log_info("After log_parse_environment");
        log_open();
        log_info("After log_open");

        umask(0022);

        if (argc != 1) {
                log_error("This program does not take arguments.");
                r = -EINVAL;
                goto finish;
        }

        r = get_user_creds(&user, &uid, &gid, NULL, NULL);
        log_info("After get_user_creds");
        if (r < 0) {
                log_error_errno(r, "Cannot resolve user name %s: %m", user);
                goto finish;
        }

        r = load_clock_timestamp(uid, gid);
        log_info("After load_clock_timestamp");
        if (r < 0)
                goto finish;
[…]

The delay is in the very beginning.

$ journalctl -u systemd-timesyncd -o short-monotonic -b
-- Logs begin at Tue 2016-09-13 14:51:22 CEST, end at Tue 2017-04-18 16:14:36 CEST. --
[    7.694166] mysystem systemd[1]: Starting Network Time Synchronization...
[    8.942021] mysystem systemd-timesyncd[311]: After log_set_target
[    8.942021] mysystem systemd-timesyncd[311]: After log_set_facility
[    8.942805] mysystem systemd-timesyncd[311]: After log_parse_environment
[    8.943063] mysystem systemd-timesyncd[311]: After log_open
[    8.943271] mysystem systemd-timesyncd[311]: After get_user_creds
[    8.943465] mysystem systemd-timesyncd[311]: load_clock_timestamp: before open /systemd/clock
[    9.103315] mysystem systemd-timesyncd[311]: load_clock_timestamp: after open /systemd/clock
[    9.103493] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, after fstat
[    9.103642] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, before timespec_load
[    9.103790] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, after timespec_load
[    9.103933] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, before fchmod
[    9.104097] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, after fchmod
[    9.104238] mysystem systemd-timesyncd[311]: load_clock_timestamp: in if, after fchown
[    9.104377] mysystem systemd-timesyncd[311]: load_clock_timestamp: before now(CLOCK_REALTIME)
[    9.104522] mysystem systemd-timesyncd[311]: load_clock_timestamp: after now(CLOCK_REALTIME)
[    9.104661] mysystem systemd-timesyncd[311]: load_clock_timestamp: before return
[    9.104801] mysystem systemd-timesyncd[311]: After load_clock_timestamp
[    9.104944] mysystem systemd-timesyncd[311]: After drop_privileges
[    9.105086] mysystem systemd-timesyncd[311]: After manager_new
[    9.298678] mysystem systemd-timesyncd[311]: After manager_parse_config_file
[    9.298894] mysystem systemd-timesyncd[311]: Before sd_notify
[    9.299048] mysystem systemd[1]: Started Network Time Synchronization.

So it looks like the delay is before calling main() of systemd-timesyncd. The machine’s performance should be pretty decent, so I welcome hints how to get to the bottom of this.