Bug 633807

Summary: semodule memory usage causes install failures on minimally configured VMs
Product: [Fedora] Fedora Reporter: Steve Tyler <stephent98>
Component: selinux-policy-targetedAssignee: Miroslav Grepl <mgrepl>
Status: CLOSED NEXTRELEASE QA Contact: Ben Levenson <benl>
Severity: medium Docs Contact:
Priority: low    
Version: 14CC: dwalsh, eparis, jbrindle, sdsmall, slawrence, tim
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-10-07 18:33:51 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
screenshot showing semodule consuming 257m resident memory
none
time series plot of memory and swap usage during minimal install
none
valgrind log for semodule
none
strace -f -tt -s 128 semodule -v -b base.pp.bz2 -i $packages -s targeted 2> $STRACE_LOG none

Description Steve Tyler 2010-09-14 13:06:38 UTC
Description of problem:
During analysis of Bug 629253, which entails installing to a minimally configured VM, it was found that installs fail during installation of selinux-policy-targeted. The failure is due to the system running out of memory, which results in anaconda and other processes being killed by the kernel.

Increasing VM memory or swap space allows the install to succeed.

While running "top" in the anaconda shell console, it is easy to see that when semodule runs there is a spike in swap usage and that semodule becomes the top memory user at over 257m resident memory.

Version-Release number of selected component (if applicable):
F13, F14 versions of selinux-policy-targeted
Fedora-14-Beta-x86_64-disc1.iso

How reproducible:
Always.

Steps to Reproduce:
Bug 629253 describes configs that result in install failures. The procedure here results in an install success so that memory usage can be observed during installation.
1. Create a VM image file of 6G.
$ qemu-img create foobar.img 6G
2. Boot from the CD disc 1 image.
$ qemu-kvm -m 512m -cdrom Fedora-14-Beta-x86_64-disc1.iso -hda foobar.img -boot menu=on
3. Select the default partitioning, a minimal install, and begin installing.
3. Switch to the anaconda shell console.
"sendkey ctrl-alt-f2" in the qemu monitor.
4. Start "top", set delay to 1 second ("d 1"), and sort by memory usage ("M").
  
Actual results:
semodule becomes top memory user.

Expected results:
semodule uses less memory during installation.

Additional info:
Bug 629253 - anaconda: system freezes on installing selinux

Comment 1 Steve Tyler 2010-09-14 13:10:22 UTC
Created attachment 447215 [details]
screenshot showing semodule consuming 257m resident memory

This was captured while "top" was running in the anaconda shell console.
Based on several trials, the peak memory usage is actually higher.

Comment 2 Daniel Walsh 2010-09-14 18:16:59 UTC
We have the ability to change the amount of memory used by semanage/semodule load by editing the /etc/selinux/semanage.conf

I guess we could have tools look at the amount of memory available then pick a more conservative compression algorithm.

Comment 3 Steve Tyler 2010-09-14 19:56:59 UTC
semodule memory usage has been noted before:

semodule memory use
Date: Wed, 10 Sep 2008 11:50:13 +1000
http://www.nsa.gov/research/selinux/list-archive/0809/thread_body38.shtml

postinst uses much RAM
Date: Wed, 20 Aug 2008 12:24:04 UTC
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=495786

Comment 4 Steve Tyler 2010-09-14 20:10:24 UTC
(In reply to comment #2)
> We have the ability to change the amount of memory used by semanage/semodule
> load by editing the /etc/selinux/semanage.conf
> 
> I guess we could have tools look at the amount of memory available then pick a
> more conservative compression algorithm.

OK, I guess you would know ... :-)

The incredible shrinking SELinux footprint
January 26th, 2009
http://danwalsh.livejournal.com/26286.html

Comment 5 Daniel Walsh 2010-09-14 20:14:49 UTC
Yup.  The problem is we traded disk space for memory.  And we need to figure a way to work for constraints on both.

Comment 6 Steve Tyler 2010-09-16 19:55:30 UTC
Out of curiosity, I did a quick-and-dirty memory usage profile of a minimal install using top. Here is the peak memory usage based on sampling every 0.1 seconds. Sorting is on RES ("The non-swapped physical memory a task has used.").

topmem - 11:49:49 up 27 min,  0 users,  load average: 1.66, 0.98, 0.44
Mem:    491984k total,   486832k used,     5152k free,      928k buffers
Swap:   983036k total,   188552k used,   794484k free,    66320k cached

%MEM  RES SWAP  VIRT  SHR CODE DATA nFLT %CPU    TIME+    PID  UID COMMAND      
55.6 267m  19m  286m  844   12 267m 1967 88.0   0:34.78  1728    0 semodule     
 1.0 4988 151m  156m 4988  208 1404    0  0.0   0:00.35    69    0 loader       
 0.6 3156  89m 94328 3156  660  16m    6  0.0   0:00.05   374    0 NetworkManage
 0.4 2040  77m 81692 2040   36  420    0  0.0   0:01.38     1    0 init         
 0.4 1840 692m  693m  316    4 167m 1122  0.0   1:26.46   438    0 anaconda     
 0.4 1732  45m 48236 1732 1572 2764    0  0.0   0:00.01   377    0 dhclient     
 0.2 1004 309m  310m  908  300 288m   15  0.0   0:00.20    53    0 rsyslogd     
 0.2  952  20m 21568  952  336  472    2  0.0   0:00.06    62   81 dbus-daemon  

Second place goes to depmod:
%MEM  RES SWAP  VIRT  SHR CODE DATA nFLT %CPU    TIME+    PID  UID COMMAND      
35.9 172m  30m  202m  584  132 198m   19 81.3   0:02.51  1774    0 depmod       

Command run on the VM from the installer's shell console was:
./topmem -b -d 0.1 | ssh stephent@walnut 'cat > tmp/topmem.2.log'
with a custom top rc file to select memory columns.

Comment 7 Steve Tyler 2010-09-17 16:44:48 UTC
Created attachment 448057 [details]
time series plot of memory and swap usage during minimal install

This plot shows the memory and swap usage over time as reported by top during a minimal install on a 512 mb VM. The total is simply the computed sum of the two.

The top memory users in time order are here:
$ cat tm2.3.csv | cut -d ':' -f 6 | uniq -c | tail -n +2
   1607 anaconda
    353 semodule
      3 loader
      1 restorecon
      7 loader
    164 anaconda
     40 depmod
    625 anaconda

A custom perl script was used to convert the top batch reports into colon separated records that can imported into gnumeric for plotting.

$ cat tm2.3.csv
rec_num:mem:swap:tot:top_frac:top_proc:anaconda:depmod:loader:restorecon:semodule
1:405360:0:405360:16.7:anaconda:1:0:0:0:0
2:405360:0:405360:16.7:anaconda:1:0:0:0:0
...
2799:485124:84480:569604:24.4:anaconda:1:0:0:0:0
2800:485124:84480:569604:24.4:anaconda:1:0:0:0:0

Comment 8 Steve Tyler 2011-05-05 21:49:45 UTC
semodule resident memory usage during a minimal install
has increased about 30% from F14 to F15.

Peak resident memory usage is in semodule:
F14: 276
F15: 357

Observed by running "top" in the installer's shell console during package installation. Sorted by memory ("M"). Delay set to one update per second.

VM configuration:
2048 MB memory.
No swap.
Full disk, formatted as ext4, "/".
Minimal install.

$ qemu-kvm -m 2048 -cdrom Fedora-14-x86_64-DVD.iso -hda ../f14-test1.img -boot menu=on
$ qemu-kvm -m 2048 -cdrom Fedora-15-Beta-x86_64-DVD.iso -hda ../f15-test1.img -boot menu=on

Comment 9 Steve Tyler 2011-05-08 21:09:44 UTC
Created attachment 497683 [details]
valgrind log for semodule

valgrind reports a few problems when running semodule. I don't know if they are significant or not.

selinux-policy-3.9.16-23.fc15.noarch
selinux-policy-targeted-3.9.16-23.fc15.noarch

Installation to the VM was with:
$ qemu-kvm -m 2048 -cdrom Fedora-15-x86_64-DVD.iso -hda ../f15-test1.img -boot menu=on

The only updates done were to 'selinux*'.

Invoked with this shell script in the VM
(based on the package script):
#!/bin/bash

#STRACE_LOG=/tmp/x$$.strace
#echo "STRACE_LOG=$STRACE_LOG"
VALGRIND_LOG=/tmp/x$$.valgrind
echo "VALGRIND_LOG=$VALGRIND_LOG"

packages=`cat /usr/share/selinux/targeted/modules.lst`
cd /usr/share/selinux/targeted 
#strace semodule -v -b base.pp.bz2 -i $packages -s targeted 2> $STRACE_LOG
valgrind --leak-check=full -v --log-file=$VALGRIND_LOG semodule -v -b base.pp.bz2 -i $packages -s targeted

Comment 10 Steve Tyler 2011-05-08 21:31:34 UTC
(In reply to comment #9)
> Created attachment 497683 [details]
> valgrind log for semodule

policycoreutils-2.0.85-27.fc15.x86_64
selinux-policy-3.9.16-23.fc15.noarch
selinux-policy-targeted-3.9.16-23.fc15.noarch
F15-TC1 DVD

Comment 11 Steve Tyler 2011-05-09 14:09:35 UTC
(In reply to comment #2)
> We have the ability to change the amount of memory used by semanage/semodule
> load by editing the /etc/selinux/semanage.conf
> 
> I guess we could have tools look at the amount of memory available then pick a
> more conservative compression algorithm.

This has no apparent effect on peak memory usage:
/etc/selinux/semanage.conf
bzip-small=True
http://selinuxproject.org/page/GlobalConfigurationFiles

The memory usage increases significantly after semodule (-v) prints:
Committing changes:

And it remains there until semodule exits.

Tested in a VM with "top" and this script:
#!/bin/bash

packages=`cat /usr/share/selinux/targeted/modules.lst`
cd /usr/share/selinux/targeted 
semodule -v -b base.pp.bz2 -i $packages -s targeted

policycoreutils-2.0.86-7.fc15.x86_64
selinux-policy-3.9.16-23.fc15.noarch
selinux-policy-targeted-3.9.16-23.fc15.noarch

Comment 12 Daniel Walsh 2011-05-09 15:00:05 UTC
# cd /usr/share/selinux/targeted
# mv base.pp.bz2 base.pp
# /usr/bin/time semodule -b base.pp -i *bz2
30.29user 6.02system 0:42.13elapsed 86%CPU (0avgtext+0avgdata 1477248maxresident)k
8392inputs+58792outputs (0major+144933minor)pagefaults 0swaps

I attempted to do something similar.

Comment 13 Daniel Walsh 2011-05-09 15:00:38 UTC
I found that the maxresident did not change.  With the bzip settings.

Comment 14 Steve Tyler 2011-05-09 18:05:01 UTC
Created attachment 497880 [details]
strace -f -tt -s 128 semodule -v -b base.pp.bz2 -i $packages -s targeted 2> $STRACE_LOG

The calls to brk() appear to be allocating far more space than is justified by the read() calls. I have no idea if that is expected ...

...
10:22:20.095003 write(1, "Committing changes:\n", 20) = 20
...
10:22:20.134300 fstat(4, {st_mode=S_IFREG|0600, st_size=13412, ...}) = 0
...
The following 4 reads: 4096*3+1124 = 13412.
...
However the brk() calls allocate:
10:22:20.134674 brk(0)                  = 0x7f3cdd329000
10:22:20.134706 brk(0x7f3cdd358000)     = 0x7f3cdd358000
10:22:20.134742 brk(0)                  = 0x7f3cdd358000
10:22:20.134773 brk(0x7f3cdd3c6000)     = 0x7f3cdd3c6000

0x7f3cdd3c6000-0x7f3cdd329000=643072

That is 643072/13412.0 = 47.9...

Test script:
#!/bin/bash

STRACE_LOG=/tmp/x$$.strace
echo "STRACE_LOG=$STRACE_LOG"
#VALGRIND_LOG=/tmp/x$$.valgrind
#echo "VALGRIND_LOG=$VALGRIND_LOG"

packages=`cat /usr/share/selinux/targeted/modules.lst`
cd /usr/share/selinux/targeted 
strace -f -tt -s 128 semodule -v -b base.pp.bz2 -i $packages -s targeted 2> $STRACE_LOG
#valgrind --leak-check=full -v --log-file=$VALGRIND_LOG semodule -v -b base.pp.bz2 -i $packages -s targeted

Comment 15 Steve Tyler 2011-05-09 18:52:54 UTC
 13412 abrt.pp.bz2
240632 abrt.pp (uncompressed)

240632/13412.0 = 17.9

Comment 16 Steve Tyler 2011-05-09 19:04:32 UTC
The average compression ratio for all of the policy files is 17.9.

$ du -b /usr/share/selinux/targeted
3710140 /usr/share/selinux/targeted

$ du -b selinux-targeted-uncompressed
66420212 selinux-targeted-uncompressed

66420212 / 3710140.0 = 17.9

Comment 17 Stephen Smalley 2011-05-09 19:13:40 UTC
Any difference from setting bzip-blocksize=0 in /etc/selinux/semanage.conf, and passing the uncompressed modules to semodule?  That should take libbz2 out of the picture.

Comment 18 Steve Tyler 2011-05-09 19:47:35 UTC
(In reply to comment #17)
> Any difference from setting bzip-blocksize=0 in /etc/selinux/semanage.conf, and
> passing the uncompressed modules to semodule?  That should take libbz2 out of
> the picture.

maxresident is slightly smaller than what Dan reported (Comment 12).
1459184 vs. 1477248.
...
Attempting to install module 'zosremote.pp':
Ok: return value of 0.
Committing changes:
Ok: transaction number 0.
30.53user 1.34system 0:37.52elapsed 84%CPU (0avgtext+0avgdata 1459184maxresident)k
0inputs+184808outputs (0major+123884minor)pagefaults 0swaps

$ grep bzip /etc/selinux/semanage.conf 
#bzip-small=True
bzip-blocksize=0

I uncompressed everything in /usr/share/selinux/targeted/ and changed modules.lst accordingly.

Test script:
#!/bin/bash

packages=`cat /usr/share/selinux/targeted/modules.lst`
cd /usr/share/selinux/targeted 
#/usr/bin/time semodule -v -b base.pp.bz2 -i $packages -s targeted
/usr/bin/time semodule -v -b base.pp -i $packages -s targeted

Comment 19 Steve Tyler 2011-05-10 10:03:58 UTC
With bzip-small enabled, the expected memory savings is about 0.35%.

"files compressed with the default 900k block size, bunzip2 will require about 3700 kbytes to decompress."
http://bzip.org/1.0.5/bzip2-manual-1.0.5.html#memory-management

$ file abrt.pp.bz2 
abrt.pp.bz2: bzip2 compressed data, block size = 900k

$ /usr/bin/time bunzip2 *.pp.bz2 
1.16user 0.13system 0:01.35elapsed 95%CPU (0avgtext+0avgdata 16512maxresident)k
0inputs+130912outputs (0major+1362minor)pagefaults 0swaps

"... bunzip2 has an option to decompress using approximately half this amount of memory, about 2300 kbytes."

$ /usr/bin/time bunzip2 -s *.pp.bz2 
3.32user 0.13system 0:03.54elapsed 97%CPU (0avgtext+0avgdata 11264maxresident)k
0inputs+130912outputs (0major+1606minor)pagefaults 0swaps

16512-11264 = 5248 k
5248/1477248.0 = 0.0035... (maxresident from Comment 12)

Comment 20 Miroslav Grepl 2011-10-07 18:33:51 UTC
We did a lot of changes in this are in F16.