Re: [systemd-devel] Strange output of `systemd-analyze critical-chain`

[Michael Biebl]

systemd-analyze and systemd-analyze critical-chain output can be
misleading sometimes.
Would it be possible for you to install systemd-bootchart.
This will give you a much better picture of which process uses IO/CPU
ressources.

2016-11-15 21:40 GMT+01:00 Paul Menzel :
> Dear systemd folks,
>
>
> I am using systemd 232-3 from Debian sid/unstable.
>
> ```
> $ systemd --version
> systemd 232
> +PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP 
> +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDNar systemd 
> folks,
> ```
>
> On the underpowered ASRock E350M1, startup is quite slow.
>
> The output of `systemd-analyze blame` also looks quite strange.
>
> ```
> $ 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 @3min 6.269s
> └─acct.service @6min 32.163s +55ms
>   └─basic.target @1min 29.644s
> └─paths.target @1min 29.639s
>   └─cups.path @1min 29.634s
> └─sysinit.target @1min 29.554s
>   └─systemd-timesyncd.service @1min 29.275s +263ms
> └─systemd-tmpfiles-setup.service @1min 28.575s +620ms
>   └─systemd-journal-flush.service @13.493s +1min 15.054s
> └─var.mount @12.408s +1.057s
>   └─systemd-fsck@dev-map\x2dvar.service @12.377s +17ms
> └─dev-mapper-speicher\x2dvar.device @12.205s
> ```
>
> It jumps from 1:30 to 6:32 minutes but the difference is shown as 55
> ms.
>
> As written, the systemd is quite underpowered. Might that be the
> reason?
>
> Here is the output of `systemd-analyze blame`.
>
> ```
> 5min 39.610s apt-daily.service
> 1min 21.012s tor@default.service
> 1min 15.054s systemd-journal-flush.service
>  1min 9.497s NetworkManager-wait-online.service
>  53.514s libvirt-guests.service
>  20.218s libvirtd.service
>  16.227s timidity.service
>  15.682s accounts-daemon.service
>  12.913s NetworkManager.service
>  12.889s vdr.service
>  11.915s apache2.service
>  11.143s ModemManager.service
>  10.434s dev-mapper-speicher\x2dusr.device
>  10.349s lirc.service
>   9.904s dev-mapper-speicher\x2droot.device
>   8.397s irqbalance.service
>   7.531s exim4.service
>   7.164s srv-bilder.mount
>   6.602s tor.service
>   6.568s lm-sensors.service
>   6.542s klogd.service
>   6.539s restorecond.service
>   6.518s rsyslog.service
>   6.509s pppd-dns.service
>   6.241s minissdpd.service
>   5.343s colord.service
>   4.982s ebtables.service
>   4.702s kdump-tools.service
>   4.631s polkit.service
>   4.620s rc-local.service
>   3.853s srv-filme.mount
>   3.302s binfmt-support.service
>   3.235s networking.service
>   3.157s lvm2-monitor.service
>   3.063s ssh.service
>   2.732s keyboard-setup.service
>   2.281s boot.mount
>   2.151s systemd-tmpfiles-setup-dev.service
>   1.915s gdm.service
>   1.857s systemd-tmpfiles-clean.service
>   1.788s console-setup.service
>   1.687s dev-mapper-speicher\x2dswap.swap
>   1.681s systemd-cryptsetup@md1_crypt.service
>   1.603s home.mount
>   1.270s iio-sensor-proxy.service
>   1.258s systemd-sysctl.service
>   1.063s systemd-random-seed.service
>   1.058s systemd-udevd.service
>   1.057s var.mount
>   1.049s speech-dispatcher.service
>   1.031s udhcpd.service
> […]
> ```
>
> Do you know what is going on?
>
>
> Thanks,
>
> Paul
> ___
> systemd-devel mailing list
> systemd-devel@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/systemd-devel
>



-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

[systemd-devel] Strange output of `systemd-analyze critical-chain`

[Paul Menzel]

Dear systemd folks,


I am using systemd 232-3 from Debian sid/unstable.

```
$ systemd --version
systemd 232
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP 
+GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDNar systemd 
folks,
```

On the underpowered ASRock E350M1, startup is quite slow.

The output of `systemd-analyze blame` also looks quite strange.

```
$ 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 @3min 6.269s
└─acct.service @6min 32.163s +55ms
  └─basic.target @1min 29.644s
    └─paths.target @1min 29.639s
  └─cups.path @1min 29.634s
    └─sysinit.target @1min 29.554s
  └─systemd-timesyncd.service @1min 29.275s +263ms
    └─systemd-tmpfiles-setup.service @1min 28.575s +620ms
  └─systemd-journal-flush.service @13.493s +1min 15.054s
    └─var.mount @12.408s +1.057s
  └─systemd-fsck@dev-map\x2dvar.service @12.377s +17ms
    └─dev-mapper-speicher\x2dvar.device @12.205s
```

It jumps from 1:30 to 6:32 minutes but the difference is shown as 55
ms.

As written, the systemd is quite underpowered. Might that be the
reason?

Here is the output of `systemd-analyze blame`.

```
5min 39.610s apt-daily.service
1min 21.012s tor@default.service
1min 15.054s systemd-journal-flush.service
 1min 9.497s NetworkManager-wait-online.service
 53.514s libvirt-guests.service
 20.218s libvirtd.service
 16.227s timidity.service
 15.682s accounts-daemon.service
 12.913s NetworkManager.service
 12.889s vdr.service
 11.915s apache2.service
 11.143s ModemManager.service
 10.434s dev-mapper-speicher\x2dusr.device
 10.349s lirc.service
  9.904s dev-mapper-speicher\x2droot.device
  8.397s irqbalance.service
  7.531s exim4.service
  7.164s srv-bilder.mount
  6.602s tor.service
  6.568s lm-sensors.service
  6.542s klogd.service
  6.539s restorecond.service
  6.518s rsyslog.service
  6.509s pppd-dns.service
  6.241s minissdpd.service
  5.343s colord.service
  4.982s ebtables.service
  4.702s kdump-tools.service
  4.631s polkit.service
  4.620s rc-local.service
  3.853s srv-filme.mount
  3.302s binfmt-support.service
  3.235s networking.service
  3.157s lvm2-monitor.service
  3.063s ssh.service
  2.732s keyboard-setup.service
  2.281s boot.mount
  2.151s systemd-tmpfiles-setup-dev.service
  1.915s gdm.service
  1.857s systemd-tmpfiles-clean.service
  1.788s console-setup.service
  1.687s dev-mapper-speicher\x2dswap.swap
  1.681s systemd-cryptsetup@md1_crypt.service
  1.603s home.mount
  1.270s iio-sensor-proxy.service
  1.258s systemd-sysctl.service
  1.063s systemd-random-seed.service
  1.058s systemd-udevd.service
  1.057s var.mount
  1.049s speech-dispatcher.service
  1.031s udhcpd.service
[…]
```

Do you know what is going on?


Thanks,

Paul

signature.asc
Description: This is a digitally signed message part
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] Spurious failures starting ConnMan with systemd

[Colin Guthrie]

Hi,

Daniel Wagner wrote on 15/11/16 15:02:
> Hi Colin,
> 
> On 11/15/2016 03:46 PM, Colin Guthrie wrote:
>> Hope you're keeping well?
> 
> Doing fine! How is live in the north? 

Grand thank you! :)

>> So, by default, dbus should be socket activated. That means that when

>> If socket activation is used, then there shouldn't be any need to
>> mention dbus.socket/service in connman.service at all.
> 
> """
> [Unit]
> Description=Connection service
> DefaultDependencies=false
> Conflicts=shutdown.target
> RequiresMountsFor=/var/lib/connman
> After=dbus.service network-pre.target systemd-sysusers.service
> Before=network.target multi-user.target shutdown.target
> Wants=network.target
...
> Hmm, now I am confused...

There may be valid reasons for not wanting some of the default
dependants but there are probably some you still want.

e.g. maybe you should do After=sockets.target (and perhaps
Requires=sockets.target although practically speaking I'm not sure if
this is needed), this would be sufficient. sockets.target is pretty low
level and can start quite early on. I suspect starting after that should
still allow connman to function as you require but without this sporadic
dbus connection issue.

HTHs

Col

-- 

Colin Guthrie
colin(at)mageia.org
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited http://www.tribalogic.net/
Open Source:
  Mageia Contributor http://www.mageia.org/
  PulseAudio Hacker http://www.pulseaudio.org/
  Trac Hacker http://trac.edgewall.org/
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] Spurious failures starting ConnMan with systemd

[Colin Guthrie]

Hey Daniel,

Hope you're keeping well?

So, by default, dbus should be socket activated. That means that when
dbus.service eventually starts shouldn't really matter, provided it is
eventually started. This is because it's actually dbus.socket that's the
important unit. It should be started by sockets.target which is pulled
in as part of the default dependencies that all units get automatically
(provided they've not disabled this)

So, check for dbus.socket, and check that connman.service doesn't
disable default deps.

If socket activation is used, then there shouldn't be any need to
mention dbus.socket/service in connman.service at all.

HTHs

Col

Daniel Wagner wrote on 15/11/16 10:59:
> [Cc: systemd mailing list"
> 
> what happened until now
> """
> I am working on a system based on Yocto Project which uses ConnMan
> v1.33 for network management. The system uses systemd and generally
> works well so far, but once in a blue moon ConnMan fails to start up.
> Here is the relevant log from systemd:
> 
> [   15.886270] systemd[1]: connman.service: Main process exited,
> code=exited, status=1/FAILURE
> [   15.912838] systemd[1]: Failed to start Connection service.
> 
> There were no logs from connmand in this case, so in the
> connman.service file I've added the -d option to ExecStart= and set
> StandardOutput to syslog. I have restarted the system many times until
> the failure occurred again. There is only a single line from connmand
> in the log:
> 
> [   12.174528] connmand[278]: Failed to connect to socket
> /var/run/dbus/system_bus_socket: No such file or directory
> [   12.209448] systemd[1]: connman.service: Main process exited,
> code=exited, status=1/FAILURE
> [   12.242872] systemd[1]: Failed to start Connection service.
> 
> So the system D-Bus is not up and running the time ConnMan is started.
> In case of failure, I've noticed there is also no mentioning about
> D-Bus starting up in the log, but in all other logs there is.
> 
> Now, I think the After=dbus.service line in src/connman.service.in is
> not enough because After= specifies order, but not a requirement
> dependency. This what Requires= is there for. I've added the line
> 
> Requires=dbus.service
> 
> to the service file, reverted my other changes, and tried again. I've
> been unable to reproduce the problem ever since, so for me the problem
> seems to be fixed.
> 
> What do you think? Should src/connman.service.in be changed to include
> the Requires= line by default or is this something to be fixed
> somewhere else?
> 
> Should network-pre.target and systemd-sysusers.service be added to
> Requires= as well?
> """
> ]
> 
> On 11/15/2016 10:45 AM, Robert Tiemann wrote:
>> On 11/14/2016 01:30 PM, Patrik Flykt wrote:
>>> On Fri, 2016-11-11 at 12:04 +0100, Daniel Wagner wrote:

 I am no systemd expert. I just did a quick read in the documentation
 and
 it seems it is recommended to have After= and Requires= together:
>>
>> Yes, this seems to be required here.
>>
 Care to send a patch which adds Requires=? Please include your
 excellent error report into the commit message.
>>
>> I can create a patch that adds Requires=dbus.service to the service
>> file if you like, but please read my comments below.
>>
>>> Hmm, then again man systemd.service says that "...Service units with
>>> this option configured implicitly gain dependencies on the dbus.socket
>>> unit. This type is the default if BusName= is specified..."
>>>
>>> ConnMan defines both Type=dbus and Busname=net.connman, so it should
>>> already have these dependencies. Unless the DefaultDependencies=false
>>> overrides this behavior. Do we have any systemd experts around?
>>
>> I am by no means a systemd expert, so instead I've tried a few things.
>> The output of
>>
>> $ systemctl show connman.service
>>
>> with the service file from v1.33 installed does not show any
>> dependencies on dbus.socket, but only an After= dependency on
>> dbus.service. The only Requires= dependency is on -.mount (and then
>> there is also the RequiredMountsFor= dependency). I always thought
>> this should be enough because dbus.service is actually required by
>> other services in the system, therefore ConnMan should be started
>> *after* it, right?
>>
>> Well. As I've come to realize, the troubles started after an upgrade
>> of ConnMan v1.30 to v1.33 a few weeks ago. So, I've checked the
>> changes of connman.service.in.
>>
>> With the service file shipped with v1.30, the output of the above
>> command shows Requires=basic.target, which depends on sockets.target,
>> which depends on dbus.socket. I think that's why I didn't have any
>> trouble with v1.30.
>>
>> In 09aa024 (first change to the service file after v1.30 release),
>> DefaultDependencies was set to false. According to
>> https://www.freedesktop.org/software/systemd/man/systemd.special.html,
>> an After= dependency on basic.target is added automatically if
>> DefaultDependencies is set to yes, so this is missing 

Re: [systemd-devel] Spurious failures starting ConnMan with systemd

[Daniel Wagner]

Hi Colin,

On 11/15/2016 03:46 PM, Colin Guthrie wrote:
> Hope you're keeping well?

Doing fine! How is live in the north? 
 
> So, by default, dbus should be socket activated. That means that when
> dbus.service eventually starts shouldn't really matter, provided it is
> eventually started. This is because it's actually dbus.socket that's the
> important unit. It should be started by sockets.target which is pulled
> in as part of the default dependencies that all units get automatically
> (provided they've not disabled this)

Okay, that makes sense.

> So, check for dbus.socket, and check that connman.service doesn't
> disable default deps.

I think we do, see below.

> If socket activation is used, then there shouldn't be any need to
> mention dbus.socket/service in connman.service at all.

"""
[Unit]
Description=Connection service
DefaultDependencies=false
Conflicts=shutdown.target
RequiresMountsFor=/var/lib/connman
After=dbus.service network-pre.target systemd-sysusers.service
Before=network.target multi-user.target shutdown.target
Wants=network.target

[Service]
Type=dbus
BusName=net.connman
Restart=on-failure
ExecStart=/usr/sbin/connmand -n
StandardOutput=null
CapabilityBoundingSet=CAP_KILL CAP_NET_ADMIN CAP_NET_BIND_SERVICE CAP_NET_RAW 
CAP_SYS_TIME CAP_SYS_MODULE
ProtectHome=true
ProtectSystem=full

[Install]
WantedBy=multi-user.target
"""

Okay, so the DefaultDependencies=false is causing this problem then.
In our commit history I found following explanation for it:

"""
commit 09aa0243aac40ec4e5bd0fbe41e702be4952a382
Author: Patrik Flykt 
Date:   Thu Sep 17 10:42:46 2015 +0300

connman.service: Fix dependencies for early boot

Unset default dependencies in order to properly run at early boot and
require the save directory to be mounted before starting.

See the systemd.unit man page, Debian's wiki page
https://wiki.debian.org/Teams/pkg-systemd/rcSMigration and the upstream
systemd-networkd.service file for details.

diff --git a/src/connman.service.in b/src/connman.service.in
index 8f7f3429f7dc..0a8f15c9f90b 100644
--- a/src/connman.service.in
+++ b/src/connman.service.in
@@ -1,7 +1,10 @@
 [Unit]
 Description=Connection service
+DefaultDependencies=false
+Conflicts=shutdown.target
+RequiresMountsFor=@localstatedir@/lib/connman
 After=dbus.service network-pre.target
-Before=network.target remote-fs-pre.target
+Before=network.target shutdown.target remote-fs-pre.target
 Wants=network.target remote-fs-pre.target
 
 [Service]
"""

Hmm, now I am confused...

Thanks,
Daniel
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel

Re: [systemd-devel] Spurious failures starting ConnMan with systemd

[Daniel Wagner]

[Cc: systemd mailing list"

what happened until now
"""
I am working on a system based on Yocto Project which uses ConnMan
v1.33 for network management. The system uses systemd and generally
works well so far, but once in a blue moon ConnMan fails to start up.
Here is the relevant log from systemd:

[   15.886270] systemd[1]: connman.service: Main process exited, 
code=exited, status=1/FAILURE

[   15.912838] systemd[1]: Failed to start Connection service.

There were no logs from connmand in this case, so in the
connman.service file I've added the -d option to ExecStart= and set
StandardOutput to syslog. I have restarted the system many times until
the failure occurred again. There is only a single line from connmand
in the log:

[   12.174528] connmand[278]: Failed to connect to socket 
/var/run/dbus/system_bus_socket: No such file or directory
[   12.209448] systemd[1]: connman.service: Main process exited, 
code=exited, status=1/FAILURE

[   12.242872] systemd[1]: Failed to start Connection service.

So the system D-Bus is not up and running the time ConnMan is started.
In case of failure, I've noticed there is also no mentioning about
D-Bus starting up in the log, but in all other logs there is.

Now, I think the After=dbus.service line in src/connman.service.in is
not enough because After= specifies order, but not a requirement
dependency. This what Requires= is there for. I've added the line

Requires=dbus.service

to the service file, reverted my other changes, and tried again. I've
been unable to reproduce the problem ever since, so for me the problem
seems to be fixed.

What do you think? Should src/connman.service.in be changed to include
the Requires= line by default or is this something to be fixed
somewhere else?

Should network-pre.target and systemd-sysusers.service be added to
Requires= as well?
"""
]

On 11/15/2016 10:45 AM, Robert Tiemann wrote:

On 11/14/2016 01:30 PM, Patrik Flykt wrote:

On Fri, 2016-11-11 at 12:04 +0100, Daniel Wagner wrote:


I am no systemd expert. I just did a quick read in the documentation
and
it seems it is recommended to have After= and Requires= together:


Yes, this seems to be required here.


Care to send a patch which adds Requires=? Please include your
excellent error report into the commit message.


I can create a patch that adds Requires=dbus.service to the service
file if you like, but please read my comments below.


Hmm, then again man systemd.service says that "...Service units with
this option configured implicitly gain dependencies on the dbus.socket
unit. This type is the default if BusName= is specified..."

ConnMan defines both Type=dbus and Busname=net.connman, so it should
already have these dependencies. Unless the DefaultDependencies=false
overrides this behavior. Do we have any systemd experts around?


I am by no means a systemd expert, so instead I've tried a few things.
The output of

$ systemctl show connman.service

with the service file from v1.33 installed does not show any
dependencies on dbus.socket, but only an After= dependency on
dbus.service. The only Requires= dependency is on -.mount (and then
there is also the RequiredMountsFor= dependency). I always thought
this should be enough because dbus.service is actually required by
other services in the system, therefore ConnMan should be started
*after* it, right?

Well. As I've come to realize, the troubles started after an upgrade
of ConnMan v1.30 to v1.33 a few weeks ago. So, I've checked the
changes of connman.service.in.

With the service file shipped with v1.30, the output of the above
command shows Requires=basic.target, which depends on sockets.target,
which depends on dbus.socket. I think that's why I didn't have any
trouble with v1.30.

In 09aa024 (first change to the service file after v1.30 release),
DefaultDependencies was set to false. According to
https://www.freedesktop.org/software/systemd/man/systemd.special.html,
an After= dependency on basic.target is added automatically if
DefaultDependencies is set to yes, so this is missing now. The After=
dependency on dbus.service is still there, but it is not Required. Out
of curiosity, I've removed the dbus.service dependency completely to
check if Type=dbus is enough as is documented. Turns out it is not.
Neither the output of "systemctl show connman.service" nor that of
"systemctl list-dependencies connman.service" show _any_ dependencies
on dbus.service/dbus.socket in this case.

Why the automatically added After= dependency on basic.target has
turned into a Requires= dependency with the v1.30 file, but the
explicit After=dbus.service dependency in the file from 09aa024
remains an After= dependency is beyond me. My guess is that
DefaultDependencies does a little bit more than is documented, or
maybe it's just a bug in my version of systemd (v225). Maybe it's some
strange interaction between unit files that I am unable to see.

A comment from someone with a little more experience with systemd
would be most