parser takes very long time to reload profile

[Arkadiusz Miśkiewicz]

I have a single policy with over 1300 hats. Reloading it takes over 3 min 30 s on 2 x Dual Core Opteron 2GHz, 6GB RAM with apparmor 2.5. The server is of course doing also other things than reloading policy but the load isn't anything big (it's like ~2).

Policy attached.

[Seth Arnold (seth-arnold)]

Wow; on my core i7 2.66 ghz, six gigs ram, your policy took 47 seconds. Good work :)

# time apparmor_parser --base `pwd` -W usr.sbin.httpd.prefork

real 0m47.289s
user 0m46.610s
sys 0m0.330s

I tried running apparmor_parser with the different DFA optimization tweaks available under the -O command line option. Most of the options made no difference for the run time, but two stood out:

no-expr-simplify cut the time down from ~47 to 22 seconds.
no-hash-part increased the time from ~47 to 72 seconds.

While trying to figure out what the different optimization options mean for the size of the compiled policy, I found a few strange behaviors in the parser.

While stracing the parser on your policy, I found that the parser called ioctl() a few thousand times:
# grep ENOTTY /tmp/out | wc -l
5369

Second, when I used -S to try to write the compiled policy to stdout, I found the parser needlessly calls dup() followed by write():

...
dup(1) = 1021
write(1021, "\4\10\0version\0\2\5\0\0\0\4\10\0profile\0\7\5+\0/"..., 17297) = 17297
dup(1) = 1022
write(1022, "\4\10\0version\0\2\5\0\0\0\4\10\0profile\0\7\5+\0/"..., 17849) = 17849
dup(1) = 1023
write(1023, "\4\10\0version\0\2\5\0\0\0\4\10\0profile\0\7\5+\0/"..., 19809) = 19809
dup(1) = -1 EMFILE (Too many open files)
write(4294967295, "\4\10\0version\0\2\5\0\0\0\4\10\0profile\0\7\5+\0/"..., 17265) = -1 EBADF (Bad file descriptor)

And just before the dup/write loop, the parser called brk 916 times:
brk(0x1bf5000) = 0x1bf5000
...
brk(0x795b000) = 0x795b000

(If my bc figuring is correct, that's about 5.7 megabytes allocated roughly 6k at a time.)

Running libmemusage shows that the parser goes through an enormous amount of memory:
heap total: 3845676047, heap peak: 105931047, stack peak: 63248

63483158 calls to malloc
203516 calls to calloc
63430608 calls to free

No wonder it takes a long time to run.

[Arkadiusz Miśkiewicz (arekm)]

Was that apparmor 2.5 tarball parser or from bzr? (fd leak was fixed in bzr some time ago)

no-expr-simplify gives me 1min 2s instead of previous 3min 30s, wow.

[John Johansen (jjohansen)]

Interesting find,

Sorry the optimization and debug option aren't properly documented yet partly because the options/names of options aren't finalized.

no-expr-simplify turns off tree expression simplification that is done before dfa creation. On simple trees it can slow down compilation some, as its an extra step that doesn't do anything beneficial, but this is well outside what it should be costing.

[John Johansen (jjohansen)]

If you are interested you can get a feel for what the dump and optimization switches are doing by looking at the backend compiler documentation I began writing at https://apparmor.wiki.kernel.org/index.php/TechnicalDoc_DFA

[Arkadiusz Miśkiewicz (arekm)]

Made a test on 3.0.13 kernel with apparmor 2.6.1 utilities.

Reloading one profile with 9486 HATs on dual core 3.06GHz intel E6600 (no load) with 4GB of ram takes only... _40 minutes_.

This is more than unusable :-/

Entire policy in txt files in 54MB. There is 1500 exactly the same hats for example with only hat name being different. This scheme occurs frequently in my policy, just with smaller values - like tons of 1-20 exactly the same hat-sets.

[Jamie Strandboge (jdstrand)]

Is this still a problem with newer AppArmor? (eg, 2.8 or 2.9)

[Launchpad Janitor (janitor)]

[Expired for AppArmor because there has been no activity for 60 days.]

[Christian Boltz (cboltz)]

2.8.4 parser still needs 44 seconds to compile an apache profile with 120 hats/vhosts.

[intrigeri (intrigeri)]

This looks very similar to https://bugs.launchpad.net/apparmor/+bug/1350598.