Spiraling Apache Server, Multiple /tmp in lsof

Matt Juszczak <matt@xxxxxxxxxx> · Tue, 14 Jul 2009 19:21:58 -0400 (EDT)

Hi all,

Working on debugging an apache server that continually keeps CPU pegged at 

100%, and load average well above 30.00.

To debug, I've set maxclients lower, and maxrequestsperchild to 0 (so that 

a tracing process doesn't continuously re-spawn).

I notice a few inefficiencies in the trace (mostly .htaccess file 

searching, which we're working on phasing out, and DNS lookups because we 

were using hostnames instead of IP's to connect to DB servers, but we're 

phasing that out as well).

But then I get to sections like this that coninuously repeat themselves, 

which is why I assume I also see processes in top hang in a "lockf" state:

 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0
 50943 httpd    CALL  fcntl(0xd,F_SETLKW,0xffffffffffffc0d0)
 50943 httpd    RET   fcntl 0

When I look up 0xd in lsof, I get:

httpd     50943       www    9u    PIPE 0xffffff008ab9c8b8              16384           ->0xffffff008ab9ca10
httpd     50943       www   10u    PIPE 0xffffff008ab9ca10                  0           ->0xffffff008ab9c8b8
httpd     50943       www   11w    VREG               0,92                  0    353317 /var (/dev/amrd0s1d)
httpd     50943       www   12u    VREG               0,93                  0        38 /tmp/aprY4bEZy
httpd     50943       www   13u    VREG               0,93                  0        39 /tmp (/dev/amrd0s1e)
httpd     50943       www   14u    VREG               0,93                  0        40 /tmp (/dev/amrd0s1e)
httpd     50943       www   15u    VREG               0,93                  0        32 /tmp (/dev/amrd0s1e)
httpd     50943       www   16u    VREG               0,93                  0        41 /tmp (/dev/amrd0s1e)
httpd     50943       www   17u    VREG               0,93                  0        34 /tmp (/dev/amrd0s1e)
httpd     50943       www   18u    VREG               0,93                  0        35 /tmp (/dev/amrd0s1e)
httpd     50943       www   19u    VREG               0,93                  0        43 /tmp (/dev/amrd0s1e)
httpd     50943       www   20u    VREG               0,93                  0        42 /tmp (/dev/amrd0s1e)
httpd     50943       www   21u    VREG               0,93                  0        45 /tmp (/dev/amrd0s1e)
httpd     50943       www   22u    VREG               0,93                  0        44 /tmp (/dev/amrd0s1e)
httpd     50943       www   23u    VREG               0,93                  0        47 /tmp (/dev/amrd0s1e)
httpd     50943       www   24u    VREG               0,93                  0        48 /tmp/aprGXHCAa
httpd     50943       www   25w    VREG               0,92                  0    353299 /var/log/accept.lock.43707
httpd     50943       www   26w    VREG               0,92                  0    353299 /var/log/accept.lock.43707
httpd     50943       www   27w    VREG               0,93                  0        48 /tmp/aprGXHCAa

I interpret 0xd to be 13, which would be /tmp.  Why are there so many 

/tmp's (is this something in the code?).  Perhaps this isn't part of the 

issue with the high load, but I know that the apache processes are timing 

out connections (and in fact, I'm getting these errors almost consistently 

right before this apache thread accepts a new connection):

 50943 httpd    CALL 

setsockopt(0x26,SOL_SOCKET,SO_RCVTIMEO,0x7fffffff70d0,0x10)

 50943 httpd    RET   setsockopt -1 errno 33 Numerical argument out of 

domain

 50943 httpd    CALL 

setsockopt(0x26,SOL_SOCKET,SO_SNDTIMEO,0x7fffffff70d0,0x10)

 50943 httpd    RET   setsockopt -1 errno 33 Numerical argument out of 

domain

and seeing a lot of:

 50943 httpd    CALL  fcntl(0x14,F_SETLK,0xffffffffffffb210)
 50943 httpd    RET   fcntl -1 errno 35 Resource temporarily unavailable

Also, with MaxRequestsPerChild set to 0, I assumed the threads would never 

re-spawn, but I monitor with ktrace and after a few minutes, it begins 

with:

 50943 httpd    RET   gettimeofday 0
 50943 httpd    CALL  read(0x1f,0x809655048,0x1f40)
 50943 httpd    GIO   fd 31 read 123 bytes
       "OPTIONS * HTTP/1.0\r

        User-Agent: Apache/2.2.11 (FreeBSD) mod_ssl/2.2.11 OpenSSL/0.9.8e 

DAV/2 (internal dummy connection)\r

        \r
       "
 50943 httpd    RET   read 123/0x7b
 50943 httpd    CALL  gettimeofday(0x7fffffffe830,0)

And then eventually dies out:

 50943 httpd    CALL  sigprocmask(SIG_SETMASK,0x80067fed0,0)
 50943 httpd    RET   sigprocmask 0
 50943 httpd    CALL  sigprocmask(SIG_BLOCK,0x80067fec0,0x7fffffffe830)
 50943 httpd    RET   sigprocmask 0
 50943 httpd    CALL  sigprocmask(SIG_SETMASK,0x80067fed0,0)
 50943 httpd    RET   sigprocmask 0
 50943 httpd    CALL  exit(0)

Thanks for any advice someone can give!

---------------------------------------------------------------------
The official User-To-User support forum of the Apache HTTP Server Project.
See <URL:http://httpd.apache.org/userslist.html> for more info.
To unsubscribe, e-mail: users-unsubscribe@xxxxxxxxxxxxxxxx
  "   from the digest: users-digest-unsubscribe@xxxxxxxxxxxxxxxx
For additional commands, e-mail: users-help@xxxxxxxxxxxxxxxx