[systemd-devel] [RFH] How to analyze long load time of `systemd-timesyncd`?

[Paul Menzel]

Dear systemd folks,


I am trying to figure out why `systemd-timesyncd` takes quite some
time, that means over 100 ms, to start up on several systems [1]. This
is also reproducible with systemd 232 from Debian Sid/unstable.

After adding `log_info()` statements to the source code, as told in
#***@irc.freenode.net, it looks like the time is spend before the
`main()` is called. Is the flow documented somewhere? Who prints
`Starting Network Time Synchronization...`, and then what happens?

It’d be awesome if you could help me, how to further debug this issue.

```
$ 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.
```


Thanks,

Paul


[1] https://github.com/systemd/systemd/issues/5024