[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
#systemd at 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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 195 bytes
Desc: This is a digitally signed message part
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20170419/f17b6b3b/attachment.sig>