From owner-freebsd-performance@FreeBSD.ORG Sun Apr 15 20:50:26 2012 Return-Path: Delivered-To: freebsd-performance@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id DCE6D106564A; Sun, 15 Apr 2012 20:50:26 +0000 (UTC) (envelope-from krichy@tvnetwork.hu) Received: from krichy.tvnetwork.hu (krichy.tvnetwork.hu [109.61.101.194]) by mx1.freebsd.org (Postfix) with ESMTP id 4C90A8FC0A; Sun, 15 Apr 2012 20:50:26 +0000 (UTC) Received: by krichy.tvnetwork.hu (Postfix, from userid 1000) id B07F7216B2; Sun, 15 Apr 2012 22:50:18 +0200 (CEST) Received: from localhost (localhost [127.0.0.1]) by krichy.tvnetwork.hu (Postfix) with ESMTP id A6A4520096; Sun, 15 Apr 2012 22:50:18 +0200 (CEST) Date: Sun, 15 Apr 2012 22:50:18 +0200 (CEST) From: Richard Kojedzinszky To: Garrett Cooper In-Reply-To: <28768C15-C694-4C09-8CD1-3F5412554B55@gmail.com> Message-ID: References: <4F8AAEF7.3090800@zedat.fu-berlin.de> <4F8B21D2.4080008@zedat.fu-berlin.de> <951B1A8C-A216-420A-BA17-316B8D9C2B0E@gmail.com> <4F8B2CC4.5030601@zedat.fu-berlin.de> <28768C15-C694-4C09-8CD1-3F5412554B55@gmail.com> User-Agent: Alpine 2.02 (DEB 1266 2009-07-14) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed X-Mailman-Approved-At: Sun, 15 Apr 2012 21:25:34 +0000 Cc: freebsd-security@freebsd.org, freebsd-performance@freebsd.org, Current FreeBSD , "O. Hartmann" Subject: Re: ufs multilabel performance (fwd) X-BeenThere: freebsd-performance@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Performance/tuning List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 15 Apr 2012 20:50:27 -0000 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^@\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^@\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 > To: O. Hartmann > Cc: freebsd-security@freebsd.org, Richard Kojedzinszky , > Current FreeBSD , > freebsd-performance@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 >>>>>> To: Richard Kojedzinszky >>>>>> Cc: freebsd-security@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 >>>>>>> To: freebsd-performance@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 <>> >>> #include >>> #include >>> #include >>> >>> 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