Poor web serving performance

[Cal Henderson]

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