Poor web serving performance
Brad Fitzpatrick
brad at danga.com
Thu Jan 25 21:25:55 UTC 2007
What's your:
SERVER aio_threads = nnnn
Set to in your config?
And can you verify that the same number of perlbal child processes are
hanging off the parent process?
On Thu, 25 Jan 2007, Cal Henderson wrote:
> hi,
>
> i'm having some problems getting decent performance out of the web
> serving portion of perlbal.
>
> i have a custom selector service, which then dispatches to a
> web_server service, using the following code:
>
> my $new_svc = Perlbal->service('my_web_server');
> $new_svc->adopt_base_client($cb);
> return 1;
>
> this all works as expected, but starts to crumble under high request
> rates (500/s is fine, 600/s is not). using http_load i start to get
> alot of "Operation already in progress" kernel errors:
>
> 150 EINPROGRESS Operation now in progress
> An operation which takes a long time to complete (such as a
> connect(2)) was attempted on a non-blocking object [see ioctl(2)].
>
> and around half of the requests to perlbal fail (perlbal never seems
> to see them). if i swap out the web server hand-off with this code:
>
> $cb->_simple_response(201, 'Fake thingy!');
> return 1;
>
> then it works as expected. if i substitute it with this code:
>
> if (-e $req->{uri}){ 0; }
> $cb->_simple_response(201, 'Fake thingy!');
> return 1;
>
> then it starts to fail again (in the same way), since it blocks on the
> non-async stat call. the reason i tried this is because the time
> *seems* to be spent doing stat's.
>
> states
> Perlbal::ClientHTTP wait_open 1
> Perlbal::ClientHTTP wait_stat 128
> Perlbal::ClientHTTP xfer_disk 262
> Perlbal::ClientHTTPBase persist_wait 2
> Perlbal::ClientHTTPBase reading_headers 320
> .
> states
> Perlbal::ClientHTTP closed 1
> Perlbal::ClientHTTP wait_stat 142
> Perlbal::ClientHTTP xfer_disk 364
> Perlbal::ClientHTTPBase persist_wait 2
> Perlbal::ClientHTTPBase reading_headers 375
>
> but maybe i'm reading it wrong. it might be something else between
> setting 'wait_stat' and 'wait_open'. hmm, nope - not the case. when i
> change the state to something else directly after the async stat call
> comes back, it still has hundreds of clients in the 'wait_stat' state.
>
> some other management console outputs:
>
> fd
> max 16384
> cur 855
> .
>
> prof data
> Perlbal::ClientHTTP-err 0.19197 0.03599 2839 0.0000676 0.0000127
> Perlbal::ClientHTTP-write 0.83087 0.22297 8880 0.0000936 0.0000251
> Perlbal::ClientHTTPBase-read 2.76559 0.34394 7187 0.0003848 0.0000479
> Perlbal::TCPListener-read 1.09684 0.12698 60 0.0182806 0.0021163
> .
>
> the disks the files reside on are mounted over NFS and are relativly
> slow, but Apache can easily serve 1000 req/s for the same files on the
> same box.
>
> i'm running this on RHEL 4, d-core d-proc 2.8Ghz w/ 3GB.
>
> [calh at pc12 Perlbal-1.53]$ uname -a
> Linux pc12.xxxxxxx.com 2.6.9-22.ELsmp #1 SMP Mon Sep 19 18:32:14 EDT
> 2005 i686 i686 i386 GNU/Linux
>
> strace says:
>
> Process 29684 detached
> % time seconds usecs/call calls errors syscall
> ------ ----------- ----------- --------- --------- ----------------
> 21.51 0.354831 10 35806 epoll_ctl
> 20.46 0.337470 10 33806 37 futex
> 7.93 0.130758 12 11134 1720 close
> 7.21 0.118962 8 14335 14331 ioctl
> 6.79 0.112034 6 19230 fcntl64
> 5.43 0.089521 6 14400 9931 _llseek
> 5.30 0.087388 13 6663 1223 read
> 5.28 0.087031 10 8686 setsockopt
> 4.70 0.077592 8 9384 time
> 4.26 0.070197 14 4981 20 accept
> 3.72 0.061351 25 2425 201 sendfile
> 2.88 0.047494 11 4371 write
> 2.14 0.035248 8 4367 fstat64
> 0.91 0.014963 365 41 epoll_wait
> 0.60 0.009821 13 729 mprotect
> 0.27 0.004423 14 326 286 stat64
> 0.25 0.004080 13 325 210 open
> 0.13 0.002194 13 170 brk
> 0.08 0.001278 128 10 clone
> 0.05 0.000749 12 60 old_mmap
> 0.03 0.000463 10 47 gettimeofday
> 0.02 0.000369 12 30 mmap2
> 0.01 0.000230 14 17 munmap
> 0.01 0.000173 173 1 execve
> 0.01 0.000171 8 21 rt_sigprocmask
> 0.01 0.000153 9 18 rt_sigaction
> 0.00 0.000081 16 5 socket
> 0.00 0.000077 15 5 pipe
> 0.00 0.000046 15 3 2 connect
> 0.00 0.000038 38 1 readlink
> 0.00 0.000038 19 2 listen
> 0.00 0.000032 16 2 waitpid
> 0.00 0.000023 12 2 bind
> 0.00 0.000020 20 1 send
> 0.00 0.000017 9 2 uname
> 0.00 0.000016 16 1 _sysctl
> 0.00 0.000014 14 1 epoll_create
> 0.00 0.000013 7 2 poll
> 0.00 0.000010 10 1 1 access
> 0.00 0.000010 10 1 recvfrom
> 0.00 0.000005 5 1 set_thread_area
> 0.00 0.000004 4 1 getpid
> 0.00 0.000004 4 1 getuid32
> 0.00 0.000004 4 1 getgid32
> 0.00 0.000004 4 1 getegid32
> 0.00 0.000004 4 1 set_tid_address
> 0.00 0.000003 3 1 getrlimit
> 0.00 0.000003 3 1 geteuid32
> ------ ----------- ----------- --------- --------- ----------------
> 100.00 1.649410 171420 27962 total
>
> anyone have any ideas?
>
>
> thanks,
>
> --cal
>
>
>
More information about the perlbal
mailing list