Connecting GPIO interfaces takes around 18 seconds

Connection GPIO interfaces in a imx6ul device takes around 18 seconds:

test@localhost:~$ time snap connect device-configuration:gpio device:gpio-85

real	0m18.196s
user	0m1.130s
sys	0m0.630s
test@localhost:~$ time snap connect device-configuration:gpio device:gpio-86

real	0m17.135s
user	0m1.030s
sys	0m0.630s

It is very common for snaps that need to access GPIO to need access to tens of them. This implies that installation times for such snaps can take minutes. It should not really take that much time to create these connections.

3 Likes

You’re absolutely correct it shouldn’t take this long.

How can I reproduce this issue? I’d like to dig a little and see what’s going on.

I would be very much interested to see what happens in the relevant change (snap changes, snap tasks NNN).

The GPIO interface uses a systemd job to export the given pin to userspace. Can you please run and paste the result here:

systemctl status snap-device-interface-gpio-85.service

I probably used the right service name but please check

@zyga-snapd this is the ouput of the commands:

test@localhost:~$ snap changes
...
23   Done    2018-04-04T16:36:27Z  2018-04-04T16:36:44Z  Connect device-configuration:gpio to device:gpio-133

test@localhost:~$ snap tasks 23
Status  Spawn                 Ready                 Summary
Done    2018-04-04T16:36:27Z  2018-04-04T16:36:28Z  Run hook prepare-plug-gpio of snap "device-configuration"
Done    2018-04-04T16:36:27Z  2018-04-04T16:36:28Z  Run hook prepare-slot-gpio-133 of snap "device"
Done    2018-04-04T16:36:27Z  2018-04-04T16:36:43Z  Connect device-configuration:gpio to device:gpio-133
Done    2018-04-04T16:36:27Z  2018-04-04T16:36:43Z  Run hook connect-slot-gpio-133 of snap "device"
Done    2018-04-04T16:36:27Z  2018-04-04T16:36:44Z  Run hook connect-plug-gpio of snap "device-configuration"

test@localhost:~$ systemctl status snap.device.interface.gpio-133.service
● snap.device.interface.gpio-133.service
   Loaded: loaded (/etc/systemd/system/snap.device.interface.gpio-133.service; enabled; vendor preset: enabled)
   Active: active (exited) since Wed 2018-04-04 16:23:13 UTC; 15h ago
  Process: 2638 ExecStart=/bin/sh -c test -e /sys/class/gpio/gpio133 || echo 133 > /sys/class/gpio/export (code=exited, st
 Main PID: 2638 (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/snap.device.interface.gpio-133.service

It looks like most of the time is spent in “Run hook prepare-slot-gpio-133”.

For x86 platforms it is faster, but still spends 3 seconds in “Run hook prepare-slot”:

admin@1234567:~$ time snap connect device-configuration:gpio caracalla:gpa-sku-gpio0

real	0m3.114s
user	0m0.068s
sys	0m0.064s

admin@1234567:~$ snap changes
ID   Status  Spawn                 Ready                 Summary
138  Done    2018-04-05T07:36:52Z  2018-04-05T07:36:55Z  Connect device-configuration:gpio to caracalla:gpa-sku-gpio0

admin@1234567:~$ snap tasks 138
Status  Spawn                 Ready                 Summary
Done    2018-04-05T07:36:52Z  2018-04-05T07:36:52Z  Run hook prepare-plug-gpio of snap "device-configuration"
Done    2018-04-05T07:36:52Z  2018-04-05T07:36:52Z  Run hook prepare-slot-gpa-sku-gpio0 of snap "caracalla"
Done    2018-04-05T07:36:52Z  2018-04-05T07:36:55Z  Connect device-configuration:gpio to caracalla:gpa-sku-gpio0
Done    2018-04-05T07:36:52Z  2018-04-05T07:36:55Z  Run hook connect-slot-gpa-sku-gpio0 of snap "caracalla"
Done    2018-04-05T07:36:52Z  2018-04-05T07:36:55Z  Run hook connect-plug-gpio of snap "device-configuration"

admin@1234567:~$ systemctl status snap.caracalla.interface.gpio-330.service 
● snap.caracalla.interface.gpio-330.service
   Loaded: loaded (/etc/systemd/system/snap.caracalla.interface.gpio-330.service; enabled; vendor preset: enabled)
   Active: active (exited) since Thu 2018-04-05 07:36:54 UTC; 49s ago
  Process: 6483 ExecStart=/bin/sh -c test -e /sys/class/gpio/gpio330 || echo 330 > /sys/class/gpio/export (code=exited, st
 Main PID: 6483 (code=exited, status=0/SUCCESS)

This is also reproducible in raspberry pi 3 [NOTE: you need the gadget snap in edge channel to see the gpio interfaces]. It takes a total of 9.5 seconds:

user@localhost:~$ time snap connect device-configuration:gpio pi3:bcm-gpio-8

real	0m9.452s
user	0m0.308s
sys	0m0.160s

user@localhost:~$ snap changes
ID   Status  Spawn                 Ready                 Summary
51   Done    2018-04-05T10:36:09Z  2018-04-05T10:36:18Z  Connect device-configuration:gpio to pi3:bcm-gpio-8

user@localhost:~$ snap tasks 51
Status  Spawn                 Ready                 Summary
Done    2018-04-05T10:36:09Z  2018-04-05T10:36:10Z  Run hook prepare-plug-gpio of snap "device-configuration"
Done    2018-04-05T10:36:09Z  2018-04-05T10:36:11Z  Run hook prepare-slot-bcm-gpio-8 of snap "pi3"
Done    2018-04-05T10:36:09Z  2018-04-05T10:36:18Z  Connect device-configuration:gpio to pi3:bcm-gpio-8
Done    2018-04-05T10:36:09Z  2018-04-05T10:36:18Z  Run hook connect-slot-bcm-gpio-8 of snap "pi3"
Done    2018-04-05T10:36:09Z  2018-04-05T10:36:18Z  Run hook connect-plug-gpio of snap "device-configuration"

user@localhost:~$ systemctl status snap.pi3.interface.gpio-8.service 
● snap.pi3.interface.gpio-8.service
   Loaded: loaded (/etc/systemd/system/snap.pi3.interface.gpio-8.service; enabled; vendor preset: enabled)
   Active: active (exited) since Thu 2018-04-05 10:36:15 UTC; 1min 35s ago
  Process: 14624 ExecStart=/bin/sh -c test -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/export (code=exited, status=0/
 Main PID: 14624 (code=exited, status=0/SUCCESS)

My Pi3 is faster ;),

untupicore@localhost:~$ time snap connect javaapp:pins pi3:bcm-gpio-8
real 0m8.819s
user 0m0.192s
sys 0m0.076s

ubuntupicore@localhost:~$ snap tasks 148
Status Spawn Ready Summary
Done 2018-04-05T10:44:01Z 2018-04-05T10:44:02Z Run hook prepare-plug-pins of snap “javaapp”
Done 2018-04-05T10:44:01Z 2018-04-05T10:44:03Z Run hook prepare-slot-bcm-gpio-8 of snap “pi3”
Done 2018-04-05T10:44:01Z 2018-04-05T10:44:08Z Connect javaapp:pins to pi3:bcm-gpio-8
Done 2018-04-05T10:44:01Z 2018-04-05T10:44:09Z Run hook connect-slot-bcm-gpio-8 of snap “pi3”
Done 2018-04-05T10:44:01Z 2018-04-05T10:44:10Z Run hook connect-plug-pins of snap “javaapp”

But i guess it can takes sometime maybe during other processes involved, so like 9 or 10 seconds is ok, I guess

Greets Tony

Can you please time the raw operation. Use systemctl cat snap.pi3.interface.gpio-8.service to see what happens. I wonder if the systemd part is slow or if the raw operation slow.

@zyga-snapd there you go:

$ systemctl cat snap.pi3.interface.gpio-8.service
# /etc/systemd/system/snap.pi3.interface.gpio-8.service
[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/bin/sh -c 'test -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/export'
ExecStop=/bin/sh -c 'test ! -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/unexport'

[Install]
WantedBy=multi-user.target

I’m sorry I wasn’t clear: I know what the unit does, I wanted you to use this command to learn that (use ExecStart) and time that

sudo -s 
time /bin/sh -c 'test -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/export'
$ sudo -s time /bin/sh -c 'test -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/export'

real	0m0.005s
user	0m0.000s
sys	0m0.008s

Thank you for testing.

Does it always take so long when you connect/disconnect that interface? I suspect it is the fact that we do systemctl daemon-reload but why is it this slow is unclear.

Strange on my Pi is this part very fast

ubuntupicore@4SJUNDCI:~$ sudo -s time /bin/sh -c 'test -e /sys/class/gpio/gpio8 || echo 8 > /sys/class/gpio/export'
real	0m0.003s
user	0m0.000s
sys	0m0.000s

Yes, it happens always. systemctl daemon-reload does not actually take that long:

$ time sudo systemctl daemon-reload

real	0m1.293s
user	0m0.072s
sys	0m0.088s

$ time snap disconnect cascade-configuration:gpio pi3:bcm-gpio-8
real	0m8.986s
user	0m0.200s
sys	0m0.132s

$ time snap connect cascade-configuration:gpio pi3:bcm-gpio-8

real	0m9.950s
user	0m0.272s
sys	0m0.132s
1 Like

And how about start/stop on that unit? That’s all snapd does.

@zyga-snapd that is quite fast in fact:

$ time sudo systemctl stop snap.pi3.interface.gpio-8.service 

real	0m0.121s
user	0m0.024s
sys	0m0.024s

$ time sudo systemctl start snap.pi3.interface.gpio-8.service

real	0m0.078s
user	0m0.024s
sys	0m0.052s

Note also that is not “this unit”, it takes long in any other system that I have tried. You can reproduce if you have an rpi3 around.

Oh, I do. Thank you for the tip, I will try to tackle this issue next week.

For what it’s worth, something’s going on with all connections taking longer than I think is reasonable. Just now on a new, beefy, lovely xeon laptop with plenty of everything, snap install sdlpop's connections took, each one of them, longer than I think is reasonable by at least a couple of orders of magnitude:

0.49s     Connect sdlpop:screen-inhibit-control to core:screen-inhibit-control
0.79s     Connect sdlpop:home to core:home
1.08s     Connect sdlpop:network-bind to core:network-bind
1.41s     Connect sdlpop:pulseaudio to core:pulseaudio
1.79s     Connect sdlpop:unity7 to core:unity7
2.17s     Connect sdlpop:network to core:network
2.59s     Connect sdlpop:opengl to core:opengl

(yes, on this machine, I’d be surprised at any of these taking more than 10ms).

Those numbers are probably the cost of running apparmor parser.

I think we could do it faster if we supported a mode where a number of connections (e.g hookless connections) are done simultaneously. We could connect all the things, compute apparmor profile once and compile that. Instead we are compiling and loading the profile once per connection, even though that all but last of those compiles are pretty much useless.

We need connection transactions perhaps. Then only the commit will compile and load apparmor profile into the kernel.

1 Like

Yes, it also looked to me that most of the time is spent by apparmor_parser. Being able to do all connections in one shot should certainly help. If snapd (and “snap connect”) could do that, it will certainly very much fix the issue on our side.

1 Like