Skip site navigation (1)Skip section navigation (2)
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, Jeremy Chadwick <freebsd@jdc.parodius.com>
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>