classic mode slow, taking up one full core with apparmor logging

[Jamie Strandboge]

On Fri, 2017-01-06 at 10:10 -0800, Dan Kegel wrote:
> When building a c++ app on a raspberry pi 3 in classic mode,
> I noticed two things that hurt performance substantially.
> 
> 1) the obvious: if you crank config.txt's gpu_mem up above the
> default, life is bad :-)  Don't do that on build machines.
> 
> 2) the not so obvious: apparmor is keeping systemctl's journal process
> at 100% on one core logging crud like
> 
> Jan 06 18:03:37 rbb-ubu1604pi3-1 audit[3249]: AVC apparmor="ALLOWED"
> operation="open"
> profile="snap.classic.classic//null-/usr/bin/systemd-run//null-
> /usr/sbin/chroot//null-/var/snap/classic/common/classic/bin/dash//null-
> /var/snap/classic/common/classic/usr/bin/script//null-
> /var/snap/classic/common/classic/bin/bash//null-
> /var/snap/classic/common/classic/usr/bin/sudo//null-
> /var/snap/classic/common/classic/bin/bash//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-repobot/bau//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-
> repobot/yovo/buildshim//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-
> repobot/yovo/cmake.d/buildshim-ubu//null-
> /var/snap/classic/common/classic/usr/bin/dpkg-buildpackage//null-
> /var/snap/classic/common/classic/home/obdank/src/yovo/debian/rules//null-
> /var/snap/classic/common/classic/usr/bin/dh//null-
> /var/snap/classic/common/classic/home/obdank/src/yovo/debian/rules//null-
> /var/snap/classic/common/classic/usr/bin/dh_auto_build//null-
> /var/snap/classic/common/classic/usr/bin/make//null-
> /var/snap/classic/common/classic/us!
>  r/bin/mak
>  e//null-/var/snap/classic/common/classic/usr/bin/make//null-
> /var/snap/classic/common/classic/bin/dash//null-
> /var/snap/classic/common/classic/usr/bin/g++-5//null-
> /var/snap/classic/common/classic/usr/lib/gcc/arm-linux-gnueabihf/5/cc1plus"
> name="/var/snap/classic/common/classic/usr/include/c++/5/cstring"
> pid=3249 comm="cc1plus" requested_mask="r" denied_mask="r" fsuid=1000
> ouid=0
> Jan 06 18:03:37 rbb-ubu1604pi3-1 audit[3254]: AVC apparmor="ALLOWED"
> operation="mknod"
> profile="snap.classic.classic//null-/usr/bin/systemd-run//null-
> /usr/sbin/chroot//null-/var/snap/classic/common/classic/bin/dash//null-
> /var/snap/classic/common/classic/usr/bin/script//null-
> /var/snap/classic/common/classic/bin/bash//null-
> /var/snap/classic/common/classic/usr/bin/sudo//null-
> /var/snap/classic/common/classic/bin/bash//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-repobot/bau//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-
> repobot/yovo/buildshim//null-
> /var/snap/classic/common/classic/home/obdank/src/ob-
> repobot/yovo/cmake.d/buildshim-ubu//null-
> /var/snap/classic/common/classic/usr/bin/dpkg-buildpackage//null-
> /var/snap/classic/common/classic/home/obdank/src/yovo/debian/rules//null-
> /var/snap/classic/common/classic/usr/bin/dh//null-
> /var/snap/classic/common/classic/home/obdank/src/yovo/debian/rules//null-
> /var/snap/classic/common/classic/usr/bin/dh_auto_build//null-
> /var/snap/classic/common/classic/usr/bin/make//null-
> /var/snap/classic/common/classic/us!
>  r/bin/mak
>  e//null-/var/snap/classic/common/classic/usr/bin/make//null-
> /var/snap/classic/common/classic/bin/dash//null-
> /var/snap/classic/common/classic/usr/bin/g++-5"
> name="/var/snap/classic/common/classic/tmp/ccpOmyw6.s" pid=3254
> comm="c++" requested_mask="c" denied_mask="c" fsuid=1000 ouid=1000
> 
> Is there an option for reducing apparmor verbosity on ALLOWED operations?
> (speaking strictly as a foreigner in the land of apparmor and snappy)
> 

What is happening is that the classic snap is currently using a chroot with
devmode. devmode causes policy violations to be allowed but logged but because
it is using a chroot instead of a pivot_root, all the file accesses don't match
the rules from the default template. To silence the logging, the policy needs to
be updated. There are several options on how to do this and it needs a little
bit of design on which implementation is best.

In the meantime, as a quick workaround you can add this to
/var/lib/snapd/apparmor/profiles/snap.classic.classic before the final '}':

  mount fstype=devpts options=(rw) devpts -> /dev/pts/,
  /bin/mountpoint ixr,
  @{PROC}/[0-9]*/mountinfo r,
  /var/lib/extrausers/{,*} r,
  capability fsetid,
  capability dac_override,
  /etc/sudoers.d/{,*} r,
  /usr/bin/systemd-run Uxr,
  /bin/systemctl Uxr,

then load the profile into the kernel with:

$ sudo apparmor_parser -r /var/lib/snapd/apparmor/profiles/snap.classic.classic

Now you should be able to 'sudo classic' and not see any apparmor logging. Note
that you may have to re-add the above rules to the profile (eg, if the snap is
removed/installed/updated/etc).

IIRC the snappy team is aware of this issue, but so it can be properly tracked,
I filed:
https://bugs.launchpad.net/snappy/+bug/1654642

-- 
Jamie Strandboge             | http://www.canonical.com

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 819 bytes
Desc: This is a digitally signed message part
URL: <https://lists.ubuntu.com/archives/snapcraft/attachments/20170106/502f7d70/attachment.sig>