mpm worker proxy: High CPU load, unresponsive

[Igor Galić]

I have a httpd with mpm worker configured as reverse proxy (it also
enflates, and encrypts where necessary, it does, as of yet, not cache)
for some 30 backends (not load balanced, mostly httpd with mpm prefork,
one with mpm worker serving Dav svn).

From time to time (about once or twice a day) my monitoring alarms that
it's gone over 90% CPU and is not responsive (from what I gather a TCP
connect works, but no HTTP talk is taking place). If this goes on for too
long, monit restarts the proxy and everything goes back to "normal".

I hooked into the process with strace at that point, only to find it do
nothing, although requests were definately made. So it's spinning at 90%
CPU, doing nothing. Even if the CPU load goes down before monit restarts
it, it's still unresponsive, so it's not self-healing. (monit will restart
it  anyway *because* it's unresponsive).

I can often see in the error log that it segfaults, but it does not
core-dump. mod_whatkilledus is mostly inconclusive, and mod_backtrace
doesn't seem to hook in:


[Sun Jul 06 11:23:18 2008] [notice] Apache/2.2.9 (Unix) mod_ssl/2.2.9 OpenSSL/0.9.8g configured -- resuming normal operations
[Sun Jul 06 11:39:17 2008] [error] [client 201.45.188.172] (70014)End of file found: proxy: error reading status line from remote server 127.0.0.1, referer: http://www.tamoggemon.com/forum/posting.php?mode=quote&p=108409
[Sun Jul 06 11:39:17 2008] [error] [client 201.45.188.172] proxy: Error reading from remote server returned by /forum/posting.php, referer: http://www.tamoggemon.com/forum/posting.php?mode=quote&p=108409
[Sun Jul 06 12:00:03 2008] [error] [client 80.253.139.90] (70014)End of file found: proxy: error reading status line from remote server 127.0.0.1, referer: http://www.freedanload.com/category/mobile-game/
[Sun Jul 06 12:00:03 2008] [error] [client 80.253.139.90] proxy: Error reading from remote server returned by /blog/contents/2006/November/thaskyforce/ships.gif, referer: http://www.freedanload.com/category/mobile-game/
[Sun Jul  6 12:00:06 2008] pid 18767 mod_whatkilledus sig 11 crash
[Sun Jul  6 12:00:06 2008] pid 18767 mod_whatkilledus active connection: 65.7.147.214:59730->78.47.99.113:80 (conn_rec a477a0)
[Sun Jul  6 12:00:06 2008] pid 18767 mod_whatkilledus active request (request_rec b9da88):GET /blog/ads/markspacebtn.gif HTTP/1.1|Accept:*/*|Referer:http%3a//tamspalm.tamoggemon.com/category/software-review/productivity/page/2/|Accept-Language:en-us|Accept-Encoding:gzip, deflate|User-Agent:Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; Q312461; .NET CLR 1.0.3705)|Host:www.tamoggemon.com|Connection:Keep-Alive
[Sun Jul  6 12:00:06 2008] pid 18767 mod_whatkilledus end of report
[Sun Jul 06 12:00:07 2008] [notice] child pid 18767 exit signal Segmentation fault (11)



My next step was to get a dump with gcore, an option I haven't been
aware of yet: (You will probably notice, that this version is without
debugging symbols)

metis:~# gdb -q $(which httpd-worker) core.1065 .1065
(no debugging symbols found)
Using host libthread_db library "/lib/libthread_db.so.1".
BFD: /lib/libm.so.6: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libm.so.6": not in executable format: File format not recognized.
BFD: /usr/lib/libpcre.so.3: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/usr/lib/libpcre.so.3": not in executable format: File format not recognized.
BFD: /lib/librt.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/librt.so.1": not in executable format: File format not recognized.
BFD: /lib/libcrypt.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libcrypt.so.1": not in executable format: File format not recognized.
BFD: /lib/libpthread.so.0: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libpthread.so.0": not in executable format: File format not recognized.
BFD: /lib/libdl.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libdl.so.2": not in executable format: File format not recognized.
BFD: /lib/libc.so.6: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libc.so.6": not in executable format: File format not recognized.
BFD: /lib64/ld-linux-x86-64.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib64/ld-linux-x86-64.so.2": not in executable format: File format not recognized.
BFD: /lib/libnss_compat.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libnss_compat.so.2": not in executable format: File format not recognized.
BFD: /lib/libnsl.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libnsl.so.1": not in executable format: File format not recognized.
BFD: /lib/libnss_nis.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libnss_nis.so.2": not in executable format: File format not recognized.
BFD: /lib/libnss_files.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libnss_files.so.2": not in executable format: File format not recognized.
BFD: /usr/lib/libz.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/usr/lib/libz.so.1": not in executable format: File format not recognized.
BFD: /usr/lib/libssl.so.0.9.8: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/usr/lib/libssl.so.0.9.8": not in executable format: File format not recognized.
BFD: /usr/lib/libcrypto.so.0.9.8: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/usr/lib/libcrypto.so.0.9.8": not in executable format: File format not recognized.
BFD: /lib/libgcc_s.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while mapping shared library sections:
"/lib/libgcc_s.so.1": not in executable format: File format not recognized.
BFD: /lib/libm.so.6: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libm.so.6": can't read symbols: File format not recognized.
BFD: /usr/lib/libpcre.so.3: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/usr/lib/libpcre.so.3": can't read symbols: File format not recognized.
Reading symbols from /opt/bw/lib/libaprutil-1.so.0...done.
Loaded symbols for /opt/bw/lib/libaprutil-1.so.0
Reading symbols from /usr/lib/libexpat.so.1...done.
Loaded symbols for /usr/lib/libexpat.so.1
Reading symbols from /opt/bw/lib/libapr-1.so.0...done.
Loaded symbols for /opt/bw/lib/libapr-1.so.0
BFD: /lib/librt.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/librt.so.1": can't read symbols: File format not recognized.
BFD: /lib/libcrypt.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libcrypt.so.1": can't read symbols: File format not recognized.
BFD: /lib/libpthread.so.0: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libpthread.so.0": can't read symbols: File format not recognized.
BFD: /lib/libdl.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libdl.so.2": can't read symbols: File format not recognized.
BFD: /lib/libc.so.6: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libc.so.6": can't read symbols: File format not recognized.
BFD: /lib/ld-linux-x86-64.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/ld-linux-x86-64.so.2": can't read symbols: File format not recognized.
BFD: /lib/libnss_compat.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libnss_compat.so.2": can't read symbols: File format not recognized.
BFD: /lib/libnsl.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libnsl.so.1": can't read symbols: File format not recognized.
BFD: /lib/libnss_nis.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libnss_nis.so.2": can't read symbols: File format not recognized.
BFD: /lib/libnss_files.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libnss_files.so.2": can't read symbols: File format not recognized.
Reading symbols from /opt/bw/libexec/apache/mod_authn_file.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_authn_file.so
Reading symbols from /opt/bw/libexec/apache/mod_authz_host.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_authz_host.so
Reading symbols from /opt/bw/libexec/apache/mod_authz_groupfile.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_authz_groupfile.so
Reading symbols from /opt/bw/libexec/apache/mod_authz_user.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_authz_user.so
Reading symbols from /opt/bw/libexec/apache/mod_authz_default.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_authz_default.so
Reading symbols from /opt/bw/libexec/apache/mod_auth_basic.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_auth_basic.so
Reading symbols from /opt/bw/libexec/apache/mod_include.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_include.so
Reading symbols from /opt/bw/libexec/apache/mod_charset_lite.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_charset_lite.so
Reading symbols from /opt/bw/libexec/apache/mod_env.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_env.so
Reading symbols from /opt/bw/libexec/apache/mod_mime_magic.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_mime_magic.so
Reading symbols from /opt/bw/libexec/apache/mod_expires.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_expires.so
Reading symbols from /opt/bw/libexec/apache/mod_headers.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_headers.so
Reading symbols from /opt/bw/libexec/apache/mod_setenvif.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_setenvif.so
Reading symbols from /opt/bw/libexec/apache/mod_mime.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_mime.so
Reading symbols from /opt/bw/libexec/apache/mod_autoindex.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_autoindex.so
Reading symbols from /opt/bw/libexec/apache/mod_negotiation.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_negotiation.so
Reading symbols from /opt/bw/libexec/apache/mod_dir.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_dir.so
Reading symbols from /opt/bw/libexec/apache/mod_alias.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_alias.so
Reading symbols from /opt/bw/libexec/apache/mod_rewrite.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_rewrite.so
Reading symbols from /opt/bw/libexec/apache/mod_proxy.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_proxy.so
Reading symbols from /opt/bw/libexec/apache/mod_proxy_http.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_proxy_http.so
Reading symbols from /opt/bw/libexec/apache/mod_proxy_connect.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_proxy_connect.so
Reading symbols from /opt/bw/libexec/apache/mod_deflate.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_deflate.so
BFD: /usr/lib/libz.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/usr/lib/libz.so.1": can't read symbols: File format not recognized.
Reading symbols from /opt/bw/libexec/apache/mod_log_config.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_log_config.so
Reading symbols from /opt/bw/libexec/apache/mod_ssl.so...done.
Loaded symbols for /opt/bw/libexec/apache/mod_ssl.so
BFD: /usr/lib/libssl.so.0.9.8: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/usr/lib/libssl.so.0.9.8": can't read symbols: File format not recognized.
BFD: /usr/lib/libcrypto.so.0.9.8: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/usr/lib/libcrypto.so.0.9.8": can't read symbols: File format not recognized.
BFD: /lib/libgcc_s.so.1: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]
Error while reading shared library symbols:
"/lib/libgcc_s.so.1": can't read symbols: File format not recognized.
BFD: /lib64/ld-linux-x86-64.so.2: don't know how to handle OS specific section `.gnu.hash' [0x6ffffff6]

warning: Unable to grok dynamic linker /lib64/ld-linux-x86-64.so.2 as an object file

warning: Unable to find dynamic linker breakpoint function.
GDB will be unable to debug shared library initializers
and track explicitly loaded dynamic code.
Core was generated by `/opt/bw/bin/httpd-worker'.
#0  0x00002b3641a815a6 in ?? ()
(gdb) where
#0  0x00002b3641a815a6 in ?? ()
#1  0x00002b3641a81470 in ?? ()
#2  0x0000000042804d38 in ?? ()
#3  0x000000000044a431 in _IO_stdin_used ()
#4  0x0000000000000000 in ?? ()

Here's some basic info:

metis:~# httpd-worker -V
Server version: Apache/2.2.9 (Unix)
Server built:   Jul  4 2008 22:52:01
Server's Module Magic Number: 20051115:15
Server loaded:  APR 1.3.0, APR-Util 1.3.0
Compiled using: APR 1.3.0, APR-Util 1.3.0
Architecture:   64-bit
Server MPM:     Worker
   threaded:     yes (fixed thread count)
     forked:     yes (variable process count)
Server compiled with....
  -D APACHE_MPM_DIR="server/mpm/worker"
  -D APR_HAS_SENDFILE
  -D APR_HAS_MMAP
  -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
  -D APR_USE_SYSVSEM_SERIALIZE
  -D APR_USE_PTHREAD_SERIALIZE
  -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
  -D APR_HAS_OTHER_CHILD
  -D AP_HAVE_RELIABLE_PIPED_LOGS
  -D DYNAMIC_MODULE_LIMIT=128

metis:~# uname -a
Linux metis 2.6.18-5-xen-amd64 #1 SMP Sat Dec 22 22:22:11 UTC 2007 x86_64 GNU/Linux
(metis is a domU)


I welcome every hint and direction you can spare and am well and ready to
provide every additional information needed.

---------------------------------------------------------------------
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@...
   "   from the digest: users-digest-unsubscribe@...
For additional commands, e-mail: users-help@...

[Nick Kew]

On Mon, 7 Jul 2008 10:15:12 +0000 (UTC)
Igor Galić <i.galic@...> wrote:

> I can often see in the error log that it segfaults, but it does not
> core-dump. mod_whatkilledus is mostly inconclusive, and mod_backtrace
> doesn't seem to hook in:

Confusing!

Couple of thoughts:
  * Does this persist if you switch back to APR-1.2.latest?
  * You said on IRC that you got the crash with a traceback
    with prefork.  Does the traceback reveal anything?


> Core was generated by `/opt/bw/bin/httpd-worker'.
> #0  0x00002b3641a815a6 in ?? ()
> (gdb) where
> #0  0x00002b3641a815a6 in ?? ()
> #1  0x00002b3641a81470 in ?? ()
> #2  0x0000000042804d38 in ?? ()
> #3  0x000000000044a431 in _IO_stdin_used ()
> #4  0x0000000000000000 in ?? ()

That's just an idle thread.  Did you try
(gdb) thread apply all bt 5


--
Nick Kew

Application Development with Apache - the Apache Modules Book
http://www.apachetutor.org/

---------------------------------------------------------------------
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@...
   "   from the digest: users-digest-unsubscribe@...
For additional commands, e-mail: users-help@...

[Igor Galić]

>> I can often see in the error log that it segfaults, but it does not
>> core-dump. mod_whatkilledus is mostly inconclusive, and mod_backtrace
>> doesn't seem to hook in:
>
> Confusing!

I wrote this mail over the last two days while collecting data, so maybe
the wording is a bit off the track ;)

> Couple of thoughts:
>  * Does this persist if you switch back to APR-1.2.latest?

I don't know, haven't tried yet, right now I also don't have a possibility
to try it out.

>  * You said on IRC that you got the crash with a traceback
>    with prefork.  Does the traceback reveal anything?

I have a couple of core dumps from different domains, and now I even found
one from yesterday that was caused by the proxy (the log does't say that
it core dumped):

Core was generated by `/opt/bw/bin/httpd-worker -f /opt/bw/etc/apache/proxy/reverse_proxy-httpd.conf'.
Program terminated with signal 11, Segmentation fault.
#0  0x00002b61978fd86b in ?? ()
(gdb) where
#0  0x00002b61978fd86b in ?? ()
#1  0x00007fff00000000 in ?? ()
#2  0x00000000006b1e78 in ?? ()
#3  0x0000000000000003 in ?? ()
#4  0x0000000000000028 in ?? ()
#5  0x000000001f5cfd7f in ?? ()
#6  0x00002b61978fdcdd in ?? ()
#7  0x0000000000000040 in ?? ()
#8  0x0000000000000010 in ?? ()
#9  0x000000029cb46fa0 in ?? ()
#10 0x0000003f00000028 in ?? ()
#11 0x00000000007d73f5 in ?? ()
#12 0x00007fff131b31e0 in ?? ()
#13 0x00007fff131b3368 in ?? ()
#14 0x0000000000000c70 in ?? ()
#15 0x0000000000000000 in ?? ()
(gdb) thread apply all bt

Thread 1 (process 22492):
#0  0x00002b61978fd86b in ?? ()
#1  0x00007fff00000000 in ?? ()
#2  0x00000000006b1e78 in ?? ()
#3  0x0000000000000003 in ?? ()
#4  0x0000000000000028 in ?? ()
#5  0x000000001f5cfd7f in ?? ()
#6  0x00002b61978fdcdd in ?? ()
#7  0x0000000000000040 in ?? ()
#8  0x0000000000000010 in ?? ()
#9  0x000000029cb46fa0 in ?? ()
#10 0x0000003f00000028 in ?? ()
#11 0x00000000007d73f5 in ?? ()
#12 0x00007fff131b31e0 in ?? ()
#13 0x00007fff131b3368 in ?? ()
#14 0x0000000000000c70 in ?? ()
#15 0x0000000000000000 in ?? ()



> --
> Nick Kew

So long,
Igor

---------------------------------------------------------------------
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@...
   "   from the digest: users-digest-unsubscribe@...
For additional commands, e-mail: users-help@...

[Igor Galić]

Should anyone be following this thread:

> > Couple of thoughts:
> >  * Does this persist if you switch back to APR-1.2.latest?
>
> I don't know, haven't tried yet, right now I also don't have a possibility
> to try it out.


Tried that now too, the result is similar:

https://issues.apache.org/bugzilla/show_bug.cgi?id=45362

As a worka-around I suppose I can lower MaxRequestsPerChild and raise
MaxSapreServers.


So long,
Igor

---------------------------------------------------------------------
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@...
   "   from the digest: users-digest-unsubscribe@...
For additional commands, e-mail: users-help@...