Date: Thu, 17 Nov 2011 12:30:27 +0400 From: Daniil Cherednik <dcherednik@masterhost.ru> To: <freebsd-stable@freebsd.org> Cc: Kostik Belousov <kostikbel@gmail.com>, Doug Barton <dougb@freebsd.org>, freebsd-apache@freebsd.org Subject: Re: 8.2 + apache == a LOT of sigprocmask Message-ID: <4EC4C623.4090207@masterhost.ru> In-Reply-To: <20111117074909.GL50300@deviant.kiev.zoral.com.ua> References: <4EC17AAF.9050807@FreeBSD.org> <4EC17F57.5030008@FreeBSD.org> <20111115090745.GO50300@deviant.kiev.zoral.com.ua> <20111115100904.GA92795@icarus.home.lan> <4EC4ADC3.2060604@FreeBSD.org> <20111117074909.GL50300@deviant.kiev.zoral.com.ua>
next in thread | previous in thread | raw e-mail | index | archive | help
On 17.11.2011 11:49, Kostik Belousov wrote: > On Wed, Nov 16, 2011 at 10:46:27PM -0800, Doug Barton wrote: >> On 11/15/2011 02:09, Jeremy Chadwick wrote: >>> On Tue, Nov 15, 2011 at 11:07:45AM +0200, Kostik Belousov wrote: >>>> On Mon, Nov 14, 2011 at 12:51:35PM -0800, Doug Barton wrote: >>>>> On 11/14/2011 12:31, Doug Barton wrote: >>>>>> Trying to track down a load problem we're seeing on 8.2-RELEASE-p4 i386 >>>>>> in a busy web hosting environment I came across the following post: >>>>>> >>>>>> http://lists.freebsd.org/pipermail/freebsd-questions/2011-October/234520.html >>>>>> >>>>>> That basically describes what we're seeing as well, including the >>>>>> "doesn't happen on Linux" part. >>>>>> >>>>>> Does anyone have any ideas about this? >>>>>> >>>>>> With incredibly similar stuff running on 7.x we didn't see this problem, >>>>>> so it seems to be something new in 8. >>>>> Just took a closer look at our ktrace, and actually our pattern is >>>>> slightly different than the one in that post. In ours the second option >>>>> is null, but the third is set: >>>>> >>>>> 74195 httpd 0.000017 RET sigprocmask 0 >>>>> 74195 httpd 0.000013 CALL sigprocmask(SIG_BLOCK,0,0xbfbf89d4) >>>>> 74195 httpd 0.000009 RET sigprocmask 0 >>>>> 74195 httpd 0.000013 CALL sigprocmask(SIG_BLOCK,0,0xbfbf89d4) >>>>> 74195 httpd 0.000009 RET sigprocmask 0 >>>>> 74195 httpd 0.000012 CALL sigprocmask(SIG_BLOCK,0,0xbfbf89d4) >>>>> >>>>> But repeated hundreds of times in a row. >>>> The calls cannot come from rtld, they are generated by some setjmp() >>>> invocation. If signal-safety is not needed, sigsetjmp() should be used >>>> instead. >>>> >>>> Quick grep of the apache httpd source shows a single setjmp() in their >>>> copy of pcre. No idea is it to safe to change setjmp() into sigsetjmp(?, 0). >>> I hate cross-posting, but: adding freebsd-apache@ to the list. Some of >>> the Apache folks (not just port committers) may have some insight to >>> Kostik's findings. >> Thanks to everyone for the responses. We tried Kostik's suggestion and >> unfortunately it didn't reduce the number of sigprocmask() calls to a >> statistically significant degree. >> >> Does anyone have any other ideas on ways to debug this? We're sort of >> running out of things to test. :-/ >> >> Given how important (and prevalent) the Apache + FreeBSD combination is, >> I'm kind of disturbed that we're seeing this performance problem, and if >> it's something in 8.x that's also in 9.x, it would be better to fix it >> prior to 9.0-RELEASE. > Since my guess appeared to be not useful, the way forward is to identify > the location of the call(s) that cause the issue. I suggest compliling > at least apache itself, libc, rtld and libthr (if used) with debugging > information. Then, attach to the running apache worker with the gdb and > set breakpoint on sigprocmask. Several backtraces from the hit breakpoint > should give enough data. > > High-tech solution is to link with libunwind and add code into sigprocmask() > to gather the stacks. But I expect that gdb attach is enough. I am sorry for repeat (I wrote about it), but what do you think about this hack: diff -u ./rtld_lock.c.orig ./rtld_lock.c --- ./rtld_lock.c.orig 2011-11-15 07:56:14.000000000 +0000 +++ ./rtld_lock.c 2011-11-15 07:54:42.000000000 +0000 @@ -118,7 +118,7 @@ sigset_t tmp_oldsigmask; for ( ; ; ) { - sigprocmask(SIG_BLOCK, &fullsigmask, &tmp_oldsigmask); +// sigprocmask(SIG_BLOCK, &fullsigmask, &tmp_oldsigmask); if (atomic_cmpset_acq_int(&l->lock, 0, WAFLAG)) break; sigprocmask(SIG_SETMASK, &tmp_oldsigmask, NULL); @@ -135,7 +135,7 @@ atomic_add_rel_int(&l->lock, -RC_INCR); else { atomic_add_rel_int(&l->lock, -WAFLAG); - sigprocmask(SIG_SETMASK, &oldsigmask, NULL); +// sigprocmask(SIG_SETMASK, &oldsigmask, NULL); } } This is one of source sigprocmask. Look: truss with original /libexec/ld-elf.so.1: #truss true __sysctl(0xbfbfe624,0x2,0xbfbfe62c,0xbfbfe630,0x0,0x0) = 0 (0x0) mmap(0x0,320,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 671633408 (0x28085000) munmap(0x28085000,320) = 0 (0x0) __sysctl(0xbfbfe688,0x2,0x2807be3c,0xbfbfe690,0x0,0x0) = 0 (0x0) mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 671633408 (0x28085000) issetugid(0x28074967,0xbfbfeb4c,0x104,0x0,0x0,0x0) = 0 (0x0) open("/etc/libmap.conf",O_RDONLY,0666) ERR#2 'No such file or directory' open("/var/run/ld-elf.so.hints",O_RDONLY,00) = 3 (0x3) read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M^E\0\0"...,128) = 128 (0x80) lseek(3,0x80,SEEK_SET) = 128 (0x80) read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,133) = 133 (0x85) close(3) = 0 (0x0) access("/lib/libc.so.7",0) = 0 (0x0) open("/lib/libc.so.7",O_RDONLY,00) = 3 (0x3) fstat(3,{ mode=-r--r--r-- ,inode=94234,size=1155172,blksize=16384 }) = 0 (0x0) pread(0x3,0x2807ad80,0x1000,0x0,0x0,0x0) = 4096 (0x1000) mmap(0x0,1159168,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671666176 (0x2808d000) mmap(0x2808d000,1040384,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 671666176 (0x2808d000) mmap(0x2818b000,24576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0xfe000) = 672706560 (0x2818b000) mprotect(0x28191000,94208,PROT_READ|PROT_WRITE) = 0 (0x0) close(3) = 0 (0x0) sysarch(0xa,0xbfbfe6f0,0x2804b3cb,0x2807a2f8,0x2805de39,0x2807a2f8) = 0 (0x0) mmap(0x0,64,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 672825344 (0x281a8000) munmap(0x281a8000,64) = 0 (0x0) mmap(0x0,21896,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 672825344 (0x281a8000) munmap(0x281a8000,21896) = 0 (0x0) 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) sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) __sysctl(0xbfbfe6a4,0x2,0x28192700,0xbfbfe6ac,0x0,0x0) = 0 (0x0) 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) sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 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) sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 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) sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) process exit, rval = 0 and truss after patching: #truss true __sysctl(0xbfbfe5a4,0x2,0xbfbfe5ac,0xbfbfe5b0,0x0,0x0) = 0 (0x0) mmap(0x0,320,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 671633408 (0x28085000) munmap(0x28085000,320) = 0 (0x0) __sysctl(0xbfbfe608,0x2,0x2807be3c,0xbfbfe610,0x0,0x0) = 0 (0x0) mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 671633408 (0x28085000) issetugid(0x28074927,0xbfbfeacc,0x104,0x0,0x0,0x0) = 0 (0x0) open("/etc/libmap.conf",O_RDONLY,0666) ERR#2 'No such file or directory' open("/var/run/ld-elf.so.hints",O_RDONLY,00) = 3 (0x3) read(3,"Ehnt\^A\0\0\0\M^@\0\0\0B\0\0\0\0"...,128) = 128 (0x80) lseek(3,0x80,SEEK_SET) = 128 (0x80) read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,66) = 66 (0x42) close(3) = 0 (0x0) access("/lib/libc.so.7",0) = 0 (0x0) open("/lib/libc.so.7",O_RDONLY,00) = 3 (0x3) fstat(3,{ mode=-r--r--r-- ,inode=12,size=1155172,blksize=16384 }) = 0 (0x0) pread(0x3,0x2807ad80,0x1000,0x0,0x0,0x0) = 4096 (0x1000) mmap(0x0,1159168,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671666176 (0x2808d000) mmap(0x2808d000,1040384,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 671666176 (0x2808d000) mmap(0x2818b000,24576,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0xfe000) = 672706560 (0x2818b000) mprotect(0x28191000,94208,PROT_READ|PROT_WRITE) = 0 (0x0) close(3) = 0 (0x0) sysarch(0xa,0xbfbfe670,0x2804b3cb,0x2807a2f8,0x2805ddf9,0x2807a2f8) = 0 (0x0) mmap(0x0,64,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 672825344 (0x281a8000) munmap(0x281a8000,64) = 0 (0x0) mmap(0x0,21896,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 672825344 (0x281a8000) munmap(0x281a8000,21896) = 0 (0x0) __sysctl(0xbfbfe624,0x2,0x28192700,0xbfbfe62c,0x0,0x0) = 0 (0x0) process exit, rval = 0 I am not expert in the internal structure of ld-elf.so, but I am trying to think there is more effective way for locks. Because now we are doing a few syscalls for each dynamic loaded library in fork time. -- С уважением, Daniil Cherednik .masterhost
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4EC4C623.4090207>