sigprocmask and fork

Wed Oct 26 20:26:00 UTC 2011

On Wed, Oct 26, 2011 at 05:02:00PM +0400, Alexandr Matveev wrote:
> Hi,
> 
> We are using FreeBSD 8.2 on our servers for high load projects.
> When I was preparing system for production I saw strange (as I think) 
> behavior,
> that leads to increased load on servers.
> 
> If I made truss on httpd (apache22) process, I saw too much sigprocmask 
> syscalls:
> 
> 24822: sigprocmask(SIG_BLOCK,0x0,0x0)            = 0 (0x0)
> 24822: sigprocmask(SIG_BLOCK,0x0,0x0)            = 0 (0x0)
> 24822: sigprocmask(SIG_BLOCK,0x0,0x0)            = 0 (0x0)
> 24822: sigprocmask(SIG_BLOCK,0x0,0x0)            = 0 (0x0)
> 24822: sigprocmask(SIG_BLOCK,0x0,0x0)            = 0 (0x0)
> ... too many lines ...
> 
> and
> 
> 24822:
> sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|S 
> 
> IGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
> 24822: sigprocmask(SIG_SETMASK,0x0,0x0)          = 0 (0x0)
> 24822:
> sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|S 
> 
> IGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
> 24822: sigprocmask(SIG_SETMASK,0x0,0x0)          = 0 (0x0)
> 24822:
> sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|S 
> 
> IGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
> 24822: sigprocmask(SIG_SETMASK,0x0,0x0)          = 0 (0x0)
> ... too many lines ...
> 
> 
> but apache, and modules loaded from it do not call this directly.
> I was trying to use DTRACE for getting information about syscalls, and I
> got same result.
> 
> I wrote a tiny sample
> 
> code:
> $ cat sigproc_test.c
> #include<unistd.h>
> 
> main()
> {
>         fork();
> }
> I ran it on FreeBSD with different compilers:
> $ cc sigproc_test.c -o sigproc_test
> $ truss ./sigproc_test 2>&1 | grep sigprocmask | wc -l
>        8
> $ g++ sigproc_test.c -o sigproc_test
> $ truss ./sigproc_test 2>&1 | grep sigprocmask | wc -l
>       20
> 
> Is it normal to make so many sigprocmask syscalls for such simple program?
> For example, there is no sigprocmask syscalls when I run it on Debian 
> Linux.
Yes, it is normal. I do not quite understand the relation between
"simple program" and "so many sigprocmask syscalls" claim, but alas.

The calls to sigprocmask originate from the rtld, which needs to
guarantee async-signal safety of the lazy binding process. The rtld
locks, besides other things, block signals. Also, due to an additional
requirement that rtld is functional after the fork, it has to acquire
the internal locks around fork in multithreaded programs.

All lock acquisions in the program which does only one fork(2) call
in main(), as well as in the program that does nothing in main at all,
come from the rtld initialization before main, and shared library
finalizations after. For empty main(), there are 4 locks acquisions
after return from main, so you get total 12 for forked version.

In essence, the trivial program makes the same amount of locking in
the startup/exit path, as non-trivial (the cost is proportional to the
number of shared libraries loaded).

The typical cause for the rtld locks acquisitions during the program
execution, besides the dlopen(3) activity, is the lazy resolution of
the PLT entries. LD_BIND_NOW=1 moves the load to the program startup.

> 
> Another sample. Here we have sigprocmask syscalls on Linux too, but 
> FreeBSD makes this syscall significantly more often:
> $ cat test.c
> #include<unistd.h>
> 
> main()
> {
>     int i;
>     sleep(2);
>     for (i = 0; i<3; i++) {
>         int pid = fork();
>         if (!pid) {
>             sleep(0.5);
>             return 0;
>         }
>         sleep(2);
>     }
> }
> 
> FreeBSD 8.2:
> # truss -f ./test
> ... SKIPPED ...
> 48666: 
> 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)
> 48666: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48666: __sysctl(0xbfbfe6a4,0x2,0x28192700,0xbfbfe6ac,0x0,0x0) = 0 (0x0)
> 48666: 
> 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)
> 48666: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48666: nanosleep({2.000000000 }) = 0 (0x0)
> 48666: fork() = 48667 (0xbe1b)
> 48667: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48667: 
> 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)
> 48667: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48667: process exit, rval = 0
> 48666: nanosleep({2.000000000 }) = 0 (0x0)
> 48666: fork() = 48669 (0xbe1d)
> 48669: 
> 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)
> 48669: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48669: process exit, rval = 0
> 48666: nanosleep({2.000000000 }) = 0 (0x0)
> 48666: fork() = 48674 (0xbe22)
> 48674: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48674: 
> 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)
> 48674: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48674: process exit, rval = 0
> 48666: nanosleep({2.000000000 }) = 0 (0x0)
> 48666: 
> 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)
> 48666: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48666: 
> 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)
> 48666: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0)
> 48666: process exit, rval = 0
> 
> Linux:
> # strace ./test
> ... SKIPPED ...
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> nanosleep({2, 0}, 0x7fff0e6b7050) = 0
> clone(child_stack=0, 
> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, 
> child_tidptr=0x7fb553b0d9d0) = 24310
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> --- SIGCHLD (Child exited) @ 0 (0) ---
> nanosleep({2, 0}, 0x7fff0e6b7050) = 0
> clone(child_stack=0, 
> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, 
> child_tidptr=0x7fb553b0d9d0) = 24311
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> --- SIGCHLD (Child exited) @ 0 (0) ---
> nanosleep({2, 0}, 0x7fff0e6b7050) = 0
> clone(child_stack=0, 
> flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, 
> child_tidptr=0x7fb553b0d9d0) = 24312
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
> --- SIGCHLD (Child exited) @ 0 (0) ---
> nanosleep({2, 0}, 0x7fff0e6b7050) = 0
> exit_group(0) = ?
> 
> -- 
> Alexander Matveev
> .masterhost
> 
> 
> _______________________________________________
> freebsd-hackers at freebsd.org mailing list
> http://lists.freebsd.org/mailman/listinfo/freebsd-hackers
> To unsubscribe, send any mail to "freebsd-hackers-unsubscribe at freebsd.org"
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 196 bytes
Desc: not available
Url : http://lists.freebsd.org/pipermail/freebsd-hackers/attachments/20111026/d21f0df3/attachment.pgp