parser takes very long time to reload profile
Bug #590113 reported by
Arkadiusz Miśkiewicz
This bug affects 1 person
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
AppArmor |
Confirmed
|
Undecided
|
Unassigned |
Bug Description
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.
tags: | added: aa-parser |
To post a comment you must log in.
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():
... 0version\ 0\2\5\0\ 0\0\4\10\ 0profile\ 0\7\5+\ 0/"..., 17297) = 17297 0version\ 0\2\5\0\ 0\0\4\10\ 0profile\ 0\7\5+\ 0/"..., 17849) = 17849 0version\ 0\2\5\0\ 0\0\4\10\ 0profile\ 0\7\5+\ 0/"..., 19809) = 19809 0version\ 0\2\5\0\ 0\0\4\10\ 0profile\ 0\7\5+\ 0/"..., 17265) = -1 EBADF (Bad file descriptor)
dup(1) = 1021
write(1021, "\4\10\
dup(1) = 1022
write(1022, "\4\10\
dup(1) = 1023
write(1023, "\4\10\
dup(1) = -1 EMFILE (Too many open files)
write(4294967295, "\4\10\
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.