autogenerated per-snap snap-update-ns apparmor profile may contain many duplicate mount rules causing excessive parser memory usage

[Jamie Strandboge]

I decided to profile the memory usage of apparmor_parser for various snap profiles and discovered that some snaps' auto-generated snap-update-ns profile had thousands of duplicate rules (particularly for snaps using the content interface multiple times). This caused a slowdown of the parser to parse the file as well as excessive memory usage. Eg:

$ for i in /var/lib/snapd/apparmor/profiles/snap*gnome-calculator ; do echo "= $i =" ; /usr/bin/time -f "wall: %E, mem: %M Kb" apparmor_parser -QTK -Ono-expr-simplify $i ; done

= /var/lib/snapd/apparmor/profiles/snap.gnome-calculator.gnome-calculator =
wall: 0:00.43, mem: 22096 Kb

= /var/lib/snapd/apparmor/profiles/snap-update-ns.gnome-calculator =
wall: 0:04.88, mem: 1541680 Kb

Whoa, almost 5 seconds to compile on a modern i7 amd64 system and 1.5G of memory used.

$ wc -l /var/lib/snapd/apparmor/profiles/snap-update-ns.gnome-calculator
17547 /var/lib/snapd/apparmor/profiles/snap-update-ns.gnome-calculator

That's a big profile. :)

Using sort -u on the profile, and then putting the preamble (ie "#include <tunables/global>" and "profile ... {") and the trailing "}" in place so that it is a proper profile, I see:

$ wc -l ./snap-update-ns.gnome-calculator.unique
662 ./snap-update-ns.gnome-calculator.unique

$ /usr/bin/time -f "wall: %E, mem: %M Kb" apparmor_parser -QTK -Ono-expr-simplify ./snap-update-ns.gnome-calculator.unique
wall: 0:00.39, mem: 36276 Kb

That's a *lot* better. Note, while my machine has 4 CPUs, using -j1 doesn't make a difference:

$ /usr/bin/time -f "wall: %E, mem: %M Kb" apparmor_parser -j1 -QTK -Ono-expr-simplify /var/lib/snapd/apparmor/profiles/snap-update-ns.gnome-calculator
wall: 0:05.32, mem: 1541236 Kb

Creating two tasks since there are 2 bugs here: snapd should not be creating a profile with so many duplicate rules and apparmor's deduplication would ideally not use so much memory.

For snapd, I suggest that when auto-generating the snap-update-ns profile, it (efficiently) dedupes before splatting out to the disk. This will cause speedups and lower memory consumption across install and refresh regardless of parser version (not to mention, smaller file sizes).

Attached are the two profiles above generated with snapd 2.42:

$ snap version
snap 2.42
snapd 2.42
series 16
ubuntu 19.04
kernel 5.0.0-29-generic

[John Johansen (jjohansen)]

The apparmor_parser does a dedup pass and a simplification pass before state machine build and minimization.

Unfortunately the parser is not applying dedup to the mount rules, and the simplification pass is disabled.

 -O expr-simplify: 2.45s RSS: 151.3 MB
 -O no-expr-simplify 3.24s RSS: 1.2 GB

The reported difference between sorted/uniqued can be fixed by fixing the dedup pass for mount rules.

[Zygmunt Krynicki (zyga)]

This is now fixed by https://github.com/snapcore/snapd/pull/7632

[Zygmunt Krynicki (zyga)]

I've iterated on the fix and I've stared implementing the spread test measuring memory usage now:

before: wall: 0:03.17, mem: 1552532 Kb
after: wall: 0:00.22, mem: 37728 Kb

Wow, what a huge difference! This is on a core i9 so the CPU time required is staggering

[Traumflug (mah-jump-ing)]

Great work!

On my 19.10 installation I found this comment in /etc/apparmor/parser.conf:

# Ubuntu LP: #1383858 - expr tree simplification is too slow for some policy on
# 32bit ARM, so disable it for now. When the parser supports it, make this
# specific to the snapd policy
Optimize=no-expr-simplify

Looking at this other LP bug, turning off simplification was a short term solution. Having the underlying issue fixed now, it might be time to remove this kludge, as suggested in the intro there.

[Zygmunt Krynicki (zyga)]

It doesn't look like the apparmor part of https://bugs.launchpad.net/ubuntu-rtm/+source/apparmor/+bug/1383858 was fixed. It was worked around hence a lot of "fix released" in various other tasks but apparmor is still triaged.

It doesn't look like anyone is working on that.

[Jamie Strandboge (jdstrand)]

While it is fine for users to adjust parser.conf to workaround this in the short term, please lets not conflate LP: #1383858 with this bug. 1383858 has actually been worked on a lot upstream with many improvements, but work remains for armhf and default optimizations for certain profile sets (including snapd's).

[Zygmunt Krynicki (zyga)]

The fix was backported and released in 2.42.1