apparmor_parser profile replace speed issues in 4.4

Curious if https://launchpad.net/ubuntu/+source/linux/4.4.0-67.88 or https://launchpad.net/ubuntu/+source/linux/4.4.0-69.90 resolves the issue for you? IIRC, I was seeing some slowness that looked like hangs in the 4.10 kernel until the patches in 67 and 69 were in there. Note: https://launchpad.net/ubuntu/+source/linux/4.4.0-70.91 reverted these patches for unrelated reasons.

This may be a duplicate of https://bugs.launchpad.net/ubuntu/+source/apparmor/+bug/1645037. If the 67 kernel fixes this for you, I think we can mark this a dupe of 1645037.

I would guess the 67 kernel should fix this for them. Those patches are being replied but I am currently unsure if they will land in the 71 kernel, as they have not been committed to it yet.

We've been testing on 67 as well as 70, 71, 72, and have only seen one instance of this issue on 67 so far. The last kernel to work without issue was 4.4.0-57.

I apologize for the lack of actual evidence here, but there's really not much going on when the issue occurs - a single apparmor_parser thread might be running, or our code might have stacked up 10 or more of them trying to reload profiles. There's not even a consistent failure mode for aa-status - it will sometimes continue to return, will sometimes pause for a seconds to minutes before returning, and sometimes immediately enter a disk-sleep state and never respond.

Any suggestions for further data collection?

Update: 4.4.0-57 is also affected.

I inspected a latent profile replace operation on a 4.4.0-72 host and watched it build a 21 megabyte /etc/apparmor.d/cache/ file over a period of 24 minutes. While I'm prepared to admit that our profiles are a bit bulky, that's still ludicrously slow.

We've now seen this issue affect both 4.8 and 4.10 series as well.

My working theory at the moment is that changes to the kernel code from 3.13 -> 4.x introduced a memory leak that's eventually overflowing.

Based on the failures we're seeing in the field, there seems to be no reliable predictor of when sysfs goes unresponsive, but the rate of occurrence is higher on machines with higher numbers of apache2 hats.

I set up a test machine with 15 hats that compiled to an ~820K cache file:

  File: '/etc/apparmor.d/cache/usr.sbin.apache2'
  Size: 819297 Blocks: 1608 IO Block: 4096 regular file

and ran apparmor_parser -rB in a loop. so far, after a dozen passes at this, the magic number at which the kernel becomes unstable is around 3 gigabytes.

Running the same test against 3.13 now, will report results

As of this writing, I've been able to load a 341Kb cache file into a 3.13.0-116 kernel over 80,000 times, for a grand total of 27 gigabytes without issue.

FWIW, Both the 4.8.0-52 and 3.13.0-116 boxes are 4 core 4 gig KVM virtual private servers.

That is worse than ludicrously slow. Something is definitely broken

@Jason,

can you tar up your profiles directory and send it to me, so I can test with your exact profile set?

attaching to this bug would work as well, if you are comfortable doing that

I'm attaching a tarball of an example apparmor directory, sanitized a bit for environment-specific things.

since the last update, I've had time to test on additional server configurations, and it does seem that the cache size required to overflow the kernel is a function of total memory - the cache file generated by this usr.sbin.apache2 profile will crash a 4 gigabyte box after ~4000 loops of `apparmor_parser -rB`, but not a larger machine.

Unfortunately, that also means I don't yet have reliable steps to reproduce the slowdown condition, as the out of memory condition happened first on the smaller test environment. I am continuing to test on an 8-core 30-gigabyte machine with additional hats.

Here's a diff of meminfo after several hundred passes vs several thousand, you can see the kernel eating memory for slabs, but it seems like we outpace slab reclamation with new allocation:

MemTotal: 4045864 kB MemTotal: 4045864 kB 3683 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:06.51 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
MemFree: 2104988 kB | MemFree: 407040 kB 3694 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.09 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
MemAvailable: 2963900 kB | MemAvailable: 1270908 kB 3792 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.44 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
Buffers: 118524 kB | Buffers: 118848 kB 3795 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
Cached: 915136 kB | Cached: 924612 kB 3796 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
SwapCached: 0 kB SwapCached: 0 kB 3797 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
Active: 815716 kB | Active: 816332 kB 3798 mysql 20 0 1281M 171M 20008 S 0.0 4.3 0:00.00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin
Inactive: 593944 kB | Inactive: 603488 kB ...

thanks,

there is definitely a memleak refcount issue going on. The rawdata info is not getting freed which exacerbates the problem, and I think why you see this in 4.4. A single profile leak can result in a much larger data set being leaked.

I am chasing it, hopefully I will have a test kernel soon.

FWIW, the out of memory condition was actually tested on a 4.8.0-52 kernel from linux-virtual-hwe-16.04

ooops, yeah sorry. It doesn't make much of a difference here as the same version of apparmor was SRUed back to 4.4, but I should still get the versioning right in the bug.

any update on this? i can still crash any 4.x kernel by reloading app armor for half an hour. 3.13 remains unaffected.

Sadly some leaks remains in all 4.x kernels. I have fixed several reference count bugs and we still have a leak happening. I am actively working on this again so hopefully we can finially get this closed.

There have been several more bug fixes, since I commented on this last. I am going to work on updating the 4.4 kernel, and build a test kernel.

Note: this is not related to Bug 1750594 which was due to the profile dedup features that were added in the 4.13 kernels.