Re: ufs multilabel performance (fwd)

Thanks for the replies.

I dont think so that perl counts anything in the test, just run the code 
with truss -D, you will see the timing that the open() syscall takes just 
more time with multilabel enabled.

Even a single touch shows that:

# truss -D touch 1
0.000056431 
mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34366259200 (0x800638000)
0.000020672 
issetugid(0x800639015,0x80062e4be,0x80084a0b0,0x80084a080,0xab57,0x0) = 0 
(0x0)
0.000060342 open("/etc/libmap.conf",O_RDONLY,0666) ERR#2 'No such file or 
directory'
0.000032964 open("/var/run/ld-elf.so.hints",O_RDONLY,057) = 3 (0x3)
0.000029891 read(3,"Ehnt\^A\0\0\0\M^_at_\0\0\0-\0\0\0\0"...,128) = 128 (0x80)
0.000063135 lseek(3,0x80,SEEK_SET)		 = 128 (0x80)
0.000040228 read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,45) = 45 (0x2d)
0.000034361 close(3)				 = 0 (0x0)
0.000031288 access("/lib/libc.so.7",0)		 = 0 (0x0)
0.000038551 open("/lib/libc.so.7",O_RDONLY,040754040) = 3 (0x3)
0.000045256 fstat(3,{ mode=-r--r--r-- 
,inode=4107,size=1306952,blksize=32768 }) = 0 (0x0)
0.000031847 
pread(0x3,0x80083c800,0x1000,0x0,0x101010101010101,0x8080808080808080) = 
4096 (0x1000)
0.000024025 
mmap(0x0,3420160,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 
34368434176 (0x80084b000)
0.000055872 
mmap(0x80084b000,1171456,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) 
= 34368434176 (0x80084b000)
0.000046095 
mmap(0x800b68000,45056,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0x11d000) 
= 34371698688 (0x800b68000)
0.000022628 
mmap(0x800b73000,110592,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) 
= 34371743744 (0x800b73000)
0.000022069 close(3)				 = 0 (0x0)
0.000024584 munmap(0x80063f000,4096)		 = 0 (0x0)
0.000030450 
mmap(0x0,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34366287872 (0x80063f000)
0.000036875 
sysarch(0x81,0x7fffffffd450,0x80063c0c8,0x0,0xffffffffffad2228,0x8080808080808080) 
= 0 (0x0)
0.000041345 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000065370 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000041066 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000032685 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000051681 readlink("/etc/malloc.conf",0x7fffffffd5e0,1024) ERR#2 'No 
such file or directory'
0.000020393 
issetugid(0x800945101,0x7fffffffd5e0,0xffffffffffffffff,0x0,0x2,0x7fffffffef79) 
= 0 (0x0)
0.000025143 break(0x800000)			 = 0 (0x0)
0.000024863 
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34371854336 (0x800b8e000)
0.000038273 
mmap(0x800f8e000,466944,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) 
= 34376048640 (0x800f8e000)
0.000025142 munmap(0x800b8e000,466944)		 = 0 (0x0)
0.000025143 gettimeofday({1334522860.892157 },0x0) = 0 (0x0)
0.000042463 stat("1",0x7fffffffdb10)		 ERR#2 'No such file or 
directory'
0.116764212 open("1",O_WRONLY|O_CREAT,0666)	 = 3 (0x3)
0.000025701 fstat(3,{ mode=-rw-r--r-- ,inode=5,size=0,blksize=32768 }) = 0 
(0x0)
0.000026819 close(3)				 = 0 (0x0)
0.000021231 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000026818 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000020952 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000032127 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
-1.999864511 process exit, rval = 0

Can you see the open()'s spent time?

Without multilabel:

# truss -D touch 1
0.000078779 
mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34366259200 (0x800638000)
0.000053078 
issetugid(0x800639015,0x80062e4be,0x80084a0b0,0x80084a080,0xab57,0x0) = 0 
(0x0)
0.000078500 open("/etc/libmap.conf",O_RDONLY,0666) ERR#2 'No such file or 
directory'
0.000039390 open("/var/run/ld-elf.so.hints",O_RDONLY,057) = 3 (0x3)
0.000034920 read(3,"Ehnt\^A\0\0\0\M^_at_\0\0\0-\0\0\0\0"...,128) = 128 (0x80)
0.000031847 lseek(3,0x80,SEEK_SET)		 = 128 (0x80)
0.000029612 read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,45) = 45 (0x2d)
0.000053357 close(3)				 = 0 (0x0)
0.000040508 access("/lib/libc.so.7",0)		 = 0 (0x0)
0.000035758 open("/lib/libc.so.7",O_RDONLY,040754040) = 3 (0x3)
0.000057828 fstat(3,{ mode=-r--r--r-- 
,inode=4107,size=1306952,blksize=32768 }) = 0 (0x0)
0.000037713 
pread(0x3,0x80083c800,0x1000,0x0,0x101010101010101,0x8080808080808080) = 
4096 (0x1000)
0.000075986 
mmap(0x0,3420160,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 
34368434176 (0x80084b000)
0.000031568 
mmap(0x80084b000,1171456,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) 
= 34368434176 (0x80084b000)
0.000048888 
mmap(0x800b68000,45056,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0x11d000) 
= 34371698688 (0x800b68000)
0.000027656 
mmap(0x800b73000,110592,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) 
= 34371743744 (0x800b73000)
0.000032405 close(3)				 = 0 (0x0)
0.000033244 munmap(0x80063f000,4096)		 = 0 (0x0)
0.000032406 
mmap(0x0,102400,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34366287872 (0x80063f000)
0.000043301 
sysarch(0x81,0x7fffffffd450,0x80063c0c8,0x0,0xffffffffffad2228,0x8080808080808080) 
= 0 (0x0)
0.000032405 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000028495 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000068443 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000030450 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000084925 readlink("/etc/malloc.conf",0x7fffffffd5e0,1024) ERR#2 'No 
such file or directory'
0.000024304 
issetugid(0x800945101,0x7fffffffd5e0,0xffffffffffffffff,0x0,0x2,0x7fffffffef79) 
= 0 (0x0)
0.000029891 break(0x800000)			 = 0 (0x0)
0.000029054 
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 
34371854336 (0x800b8e000)
0.000025701 
mmap(0x800f8e000,466944,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) 
= 34376048640 (0x800f8e000)
0.000063135 munmap(0x800b8e000,466944)		 = 0 (0x0)
0.000030171 gettimeofday({1334522939.716792 },0x0) = 0 (0x0)
0.000464296 stat("1",0x7fffffffdb10)		 ERR#2 'No such file or 
directory'
0.000612356 open("1",O_WRONLY|O_CREAT,0666)	 = 3 (0x3)
0.000034082 fstat(3,{ mode=-rw-r--r-- ,inode=4,size=0,blksize=32768 }) = 0 
(0x0)
0.000058945 close(3)				 = 0 (0x0)
0.000027377 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000032685 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
0.000026818 
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) 
= 0 (0x0)
0.000023746 sigprocmask(SIG_SETMASK,0x0,0x0)	 = 0 (0x0)
-1.999924294 process exit, rval = 0

Maybe the factor is not this much in real installations, not as in my 
domU, but still it is slow.

Regards,
Kojedzinszky Richard
Euronet Magyarorszag Informatikai Zrt.

On Sun, 15 Apr 2012, Garrett Cooper wrote:

> Date: Sun, 15 Apr 2012 13:35:59 -0700
> From: Garrett Cooper <yanegomi_at_gmail.com>
> To: O. Hartmann <ohartman_at_zedat.fu-berlin.de>
> Cc: freebsd-security_at_freebsd.org, Richard Kojedzinszky <krichy_at_tvnetwork.hu>,
>     Current FreeBSD <freebsd-current_at_freebsd.org>,
>     freebsd-performance_at_freebsd.org
> Subject: Re: ufs multilabel performance (fwd)
> 
> On Apr 15, 2012, at 1:17 PM, O. Hartmann wrote:
>
>> Am 04/15/12 22:00, schrieb Garrett Cooper:
>>> On Apr 15, 2012, at 12:30 PM, O. Hartmann wrote:
>>>
>>>> Am 04/15/12 15:59, schrieb Richard Kojedzinszky:
>>>>> Thank you for the reply.
>>>>>
>>>>> Unfortunately, dont know why, but on my xen virtualised environment,
>>>>> fbsd amd64 domU performs much slower, not only 30 times. Without
>>>>> multilabel, file creation speed is around 2500/s, but with multilabels
>>>>> enabled, it is only 15/s (!). so it is more than 100 times slower.
>>>>>
>>>>> And anyway freebsd is known to be fast as well, as functional. The power
>>>>> to serve. :)
>>>>>
>>>>> But in my environment, 15/s file creation is very-very slow. The
>>>>> hardware is a q6700 cpu with 4G ram, 2x1T sata disks in raid1, the host
>>>>> runs linux. I think with this hw the mentioned speed is really slow.
>>>>>
>>>>> Regards,
>>>>>
>>>>>
>>>>> Kojedzinszky Richard
>>>>> Euronet Magyarorszag Informatikai Zrt.
>>>>>
>>>>> On Sun, 15 Apr 2012, O. Hartmann wrote:
>>>>>
>>>>>> Date: Sun, 15 Apr 2012 13:20:23 +0200
>>>>>> From: O. Hartmann <ohartman_at_zedat.fu-berlin.de>
>>>>>> To: Richard Kojedzinszky <krichy_at_tvnetwork.hu>
>>>>>> Cc: freebsd-security_at_freebsd.org
>>>>>> Subject: Re: ufs multilabel performance (fwd)
>>>>>>
>>>>>> Am 04/14/12 21:37, schrieb Richard Kojedzinszky:
>>>>>>> Dear list,
>>>>>>>
>>>>>>> Although it is not only security-related question, I did not get any
>>>>>>> answer from freebsd-performance. The original question is below.
>>>>>>>
>>>>>>> Can someone give some advice?
>>>>>>>
>>>>>>> Thanks in advance,
>>>>>>>
>>>>>>>
>>>>>>> Kojedzinszky Richard
>>>>>>> Euronet Magyarorszag Informatikai Zrt.
>>>>>>>
>>>>>>> ---------- Forwarded message ----------
>>>>>>> Date: Thu, 10 Nov 2011 06:16:57 +0100 (CET)
>>>>>>> From: Richard Kojedzinszky <krichy_at_tvnetwork.hu>
>>>>>>> To: freebsd-performance_at_freebsd.org
>>>>>>> Subject: ufs multilabel performance
>>>>>>>
>>>>>>> Dear List,
>>>>>>>
>>>>>>> I've noticed that when I enable multilabel on an fs, a file creation
>>>>>>> gets around 20-30 times slower than without multilabel set.
>>>>>>>
>>>>>>> This one-liner can be used to test the differences:
>>>>>>> $ truss -D perl -e 'open(F, ">$_.file") for 1 .. 1000'
>>>>>>
>>>>>> Same here, creating files seems to be 10 - 30 times slower with
>>>>>> multilabels as it is without.
>>>>>>
>>>>>> But as several posts and discussions reflects, FreeBSD isn't supposed to
>>>>>> be fast although it is claimed that writing is the major than reading;
>>>>>> FBSD should serve functionality.
>>>>>>>
>>>>>>> And one can see that the open call takes much more when multilabel is
>>>>>>> set on an fs. It seems that only file creation needs that many time,
>>>>>>> when a file exists it is opened much faster.
>>>>>>>
>>>>>>> Could someone acknowledge this, and have some suggestions how to make it
>>>>>>> faster?
>>>>>>>
>>>>>>> Regards,
>>>>>>>
>>>>>>>
>>>>>>> Kojedzinszky Richard
>>>>>>> TvNetWork Nyrt.
>>>>>>> E-mail: krichy (at) tvnetwork [dot] hu
>>>>>>> PGP: 0x54B2BF0C8F59B1B7
>>>>>>> Fingerprint = F6D4 3FFE AF03 CACF 0DCB  46A1 54B2 BF0C 8F59 B1B7
>>>>
>>>> At the moment, I'm troubled with a nasty kernel bug on all FreeBSD 10
>>>> boxes I have spare to test.
>>>>
>>>> I just tried to reproduce your observation and as far as I can go with
>>>> my experience, I can confirm that by using your perl script.
>>>>
>>>> I'd like to test this again with a small C program.
>>>>
>>>> I can only test the issue (test is too far optimistic, it's simply a
>>>> reproduction of your observation) on FreeBSD 10, the only remaining
>>>> FreeBSD server at our department is running FBSD 9-STABLE/amd64 and "in
>>>> production", so changing multilabel support is a bit harsh at the moment.
>>>>
>>>>
>>>> Sorry about crossposting, but I think this belongs more to CURRENT and
>>>> PERFORMANCE than SECURITY.
>>>
>>> My suggestion is completely take perl out of the equation because the way you're invoking it above uses stdio and a few other things that add unnecessary overhead.
>>>
>>> Try the attached C program/bourne shell snippet instead.
>>>
>>> Cheers,
>>> -Garrett
>>>
>>> #!/bin/sh
>>>
>>> set -e
>>>
>>> tmp=$(mktemp -d tmp.XXXXXX)
>>> trap "cd /; rm -Rf $tmp" EXIT
>>> cd $tmp
>>>
>>> cat > test_open.c <<EOF
>>>
>>> #include <fcntl.h>
>>> #include <stdio.h>
>>> #include <unistd.h>
>>>
>>> int
>>> main(void)
>>> {
>>>        char buf[20];
>>>        int i;
>>>
>>>        for (i = 0; i < 1000; i++) {
>>>                sprintf(buf, "%d", i);
>>>                close(open(buf, O_WRONLY|O_CREAT, 0600));
>>>        }
>>>        return (0);
>>> }
>>> EOF
>>>
>>> gcc -o test_open test_open.c
>>> time ./test_open_______________________________________________
>>
>> This was pretty fast ;-)
>
> 	If it turns out that it wasn't that particular item that's causing a slowdown, I can easily modify my above snippet to use stdio, etc. But unless the version of perl and a few other items are the same, I wouldn't necessarily blame the guest OS. Please also make sure that Xen, etc is completely up-to-date because there were some performance degradation issues that were fixed post-6.0.
> -Garrett