As part of the ongoing story of measuring and improving snapd performance [1] I took a look at the performance of the apparmor parser on pi3, with focus on the pessimistic case where all apparmor profiles need to be regenerated on snapd startup due to system-key change or change to profiles themselves (this doesn’t happen very often but when it does, it can have significant impact on snapd startup time, depending on the number of snaps in the system).
For the test a pi3 with core18 has been used, and 11 random snaps from the store.
The test
To force refreshing of all profiles, I had manually modified all of them and also manually changed the system-key, then rebooted the system. snapd recognized the changes and recreated all profiles, startup timings look as follows:
$ snap debug timings --startup=ifacemgr
ID Status Doing Undoing Summary
ifacemgr - -
^ 27ms - setup security backend "seccomp" for snap "doctl"
^ 670ms - setup security backend "apparmor" for snap "doctl"
^ 622ms - load changed security profiles of snap "doctl"
^ 11ms - load unchanged security profiles of snap "doctl"
^ 8ms - setup security backend "seccomp" for snap "hello-world"
^ 834ms - setup security backend "apparmor" for snap "hello-world"
^ 593ms - load changed security profiles of snap "hello-world"
^ 11ms - load unchanged security profiles of snap "hello-world"
^ 88ms - setup security backend "seccomp" for snap "hugo"
^ 678ms - setup security backend "apparmor" for snap "hugo"
^ 626ms - load changed security profiles of snap "hugo"
^ 11ms - load unchanged security profiles of snap "hugo"
^ 24ms - setup security backend "apparmor" for snap "snapd"
^ 731ms - setup security backend "apparmor" for snap "ascii-patrol"
^ 683ms - load changed security profiles of snap "ascii-patrol"
^ 11ms - load unchanged security profiles of snap "ascii-patrol"
^ 81ms - setup security backend "seccomp" for snap "nano-strict"
^ 619ms - setup security backend "apparmor" for snap "nano-strict"
^ 523ms - load changed security profiles of snap "nano-strict"
^ 11ms - load unchanged security profiles of snap "nano-strict"
^ 601ms - setup security backend "apparmor" for snap "pi"
^ 458ms - load changed security profiles of snap "pi"
^ 11ms - load unchanged security profiles of snap "pi"
^ 527ms - setup security backend "apparmor" for snap "core"
^ 471ms - load changed security profiles of snap "core"
^ 11ms - load unchanged security profiles of snap "core"
^ 580ms - setup security backend "apparmor" for snap "htop"
^ 457ms - load changed security profiles of snap "htop"
^ 11ms - load unchanged security profiles of snap "htop"
Just for the record, unchanged profiles (if only system-key changes but apparmor profiles are the same) takes just a fraction of that:
$ snap debug timings --startup=ifacemgr
ID Status Doing Undoing Summary
ifacemgr - -
^ 6ms - setup security backend "seccomp" for snap "hello-world"
^ 80ms - setup security backend "apparmor" for snap "hello-world"
^ 24ms - load unchanged security profiles of snap "hello-world"
^ 32ms - setup security backend "apparmor" for snap "ascii-patrol"
^ 18ms - load unchanged security profiles of snap "ascii-patrol"
^ 34ms - setup security backend "apparmor" for snap "core"
^ 16ms - load unchanged security profiles of snap "core"
^ 32ms - setup security backend "apparmor" for snap "doctl"
^ 18ms - load unchanged security profiles of snap "doctl"
^ 22ms - setup security backend "apparmor" for snap "snapd"
^ 30ms - setup security backend "apparmor" for snap "htop"
^ 16ms - load unchanged security profiles of snap "htop"
^ 32ms - setup security backend "apparmor" for snap "hugo"
^ 18ms - load unchanged security profiles of snap "hugo"
^ 39ms - setup security backend "apparmor" for snap "nano-strict"
^ 17ms - load unchanged security profiles of snap "nano-strict"
^ 29ms - setup security backend "apparmor" for snap "pi"
^ 16ms - load unchanged security profiles of snap "pi"
Back to the pessimistic scenario. I had tested same scenario with manual invocation of aa_parser, using same command line arguments as snapd when loading changed profiles, e.g.
apparmor_parser --replace --write-cache -O no-expr-simplify --cache-loc=/etc/apparmor.d/cache --skip-read-cache --quiet /var/lib/snapd/apparmor/profiles/<profilename>
Running this via time ...
over all profiles on-by-one resulted in the following timings:
real 0m0.650s
user 0m0.631s
sys 0m0.017s
real 0m0.459s
user 0m0.439s
sys 0m0.019s
real 0m0.631s
user 0m0.610s
sys 0m0.019s
real 0m0.465s
user 0m0.436s
sys 0m0.028s
real 0m0.472s
user 0m0.454s
sys 0m0.016s
real 0m0.467s
user 0m0.443s
sys 0m0.023s
real 0m0.463s
user 0m0.434s
sys 0m0.028s
real 0m0.453s
user 0m0.436s
sys 0m0.015s
real 0m0.642s
user 0m0.631s
sys 0m0.009s
real 0m0.467s
user 0m0.451s
sys 0m0.015s
real 0m0.469s
user 0m0.444s
sys 0m0.023s
real 0m0.467s
user 0m0.452s
sys 0m0.013s
(note there 12 samples, not 11, because the number of profiles >= number of snaps, depending on apps/hooks).
The total time of all the invokations of aa_parser was:
real 0m6.108s
user 0m5.862s
sys 0m0.228s
To summarize this test, both forceful refresh of all profiles via snapd’s invocation of aa_parser, as well as manual invocation over all profiles on-by-one just like snapd does it gave identical results (as expected) - each invocation took approximately 0.5s, taking 6s total to process all profiles of 12 snaps.
Combined reload of all profiles
The second test is about testing a single invocation of aa_parser against all profiles at once, which is a possible optimization we can do in snapd. This obviously can only be tested manually, e.g.
time /sbin/apparmor_parser --replace --write-cache -O no-expr-simplify --cache-loc=/etc/apparmor.d/cache --skip-read-cache --quiet /var/lib/snapd/apparmor/profiles/snap.*
This gives:
real 0m1.979s
user 0m7.054s
sys 0m0.212s
This is over 3 times faster than when invoking aa_parser multiple times on a slow system such as pi3 (!).
What about PC
Results on a fast PC (amd64) seem to match these trends although total numbers are obviously less spectacular. With 13 snaps on my test PC (amd64 3GHz, 4 cores) it takes 1.5s to regenerate all profiles with multiple invocations of aa_parser, and 0.5s if combined into a single invocation; this will of course be amplified with more snaps on the system.
For the record, the script I used to collect the timings:
#!/bin/bash
AADIR=/var/lib/snapd/apparmor/profiles
{
time (
for AAPROF in $AADIR/snap.*; do
time /sbin/apparmor_parser --replace --write-cache -O no-expr-simplify --cache-loc=/etc/apparmor.d/cache --skip-read-cache --quiet "$AAPROF"
done
) } 2> timings-total-separate.txt
( time /sbin/apparmor_parser --replace --write-cache -O no-expr-simplify --cache-loc=/etc/apparmor.d/cache --skip-read-cache --quiet $AADIR/snap.* ) > timings-total-combined.txt 2>&1
[1] Some of that brought fruit already in the form of snap debug timings ...
infrastructure, as well as optimization of auto-connections on install (tha later will become available in snapd 2.42).