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