php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #58437 Hung httpd processes, futex/mutex
Submitted: 2008-11-28 08:25 UTC Modified: 2011-02-14 18:25 UTC
From: ormandj at gmail dot com Assigned:
Status: Closed Package: APC (PECL)
PHP Version: 5.1.6 OS: RHEL 5.2
Private report: No CVE-ID: None
 [2008-11-28 08:25 UTC] ormandj at gmail dot com
Description:
------------
Hi,

When utilized on a relatively heavily accessed website, I am encountering hung httpd processes when APC 3.0.19 is in use.

Here is the output from gdb to a process, as well as strace output:

(gdb) backtrace
#0 0x00002b6d41480888 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1 0x00002b6d4147c8a5 in _L_mutex_lock_107 () from /lib64/libpthread.so.0
#2 0x00002b6d4147c333 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x00002b6d4d5885b9 in apc_pthreadmutex_lock (lock=0x2b6d51072070) at /root/APC-3.0.19/apc_pthreadmutex.c:72
#4 0x00002b6d4d582d49 in apc_cache_find_slot (cache=0x2b6d5c23bfc0, key=
{data = {file = {device = 2053, inode = 3932326}, user = {identifier = 0x805 "\001", identifier_len = 3932326}, fpfile = {fullpath = 0x805 "\001", fullpath_len = 3932326}}, mtime = 1123687688, type = 1 '\001'}, t=1227181723) at /root/APC-3.0.19/apc_cache.c:520
#5 0x00002b6d4d582f10 in apc_cache_find (cache=0x2b6d51072070, key=
{data = {file = {device = 2053, inode = 3932326}, user = {identifier = 0x805 "\001", identifier_len = 3932326}, fpfile = {fullpath = 0x805 "\001", fullpath_len = 3932326}}, mtime = 1123687688, type = 1 '\001'}, t=0) at /root/APC-3.0.19/apc_cache.c:568
#6 0x00002b6d4d5876f8 in my_compile_file (h=0x7fff6b138990, type=2) at /root/APC-3.0.19/apc_main.c:343
#7 0x00002b6d4b20d15b in zend_execute_scripts () from /etc/httpd/modules/libphp5.so
#8 0x00002b6d4b1d22c7 in php_execute_script () from /etc/httpd/modules/libphp5.so
#9 0x00002b6d4b28a6c6 in php_ap2_register_hook () from /etc/httpd/modules/libphp5.so
#10 0x00002b6d3f9997ea in ap_run_handler () from /usr/sbin/httpd
#11 0x00002b6d3f99cc62 in ap_invoke_handler () from /usr/sbin/httpd
#12 0x00002b6d3f9a7618 in ap_process_request () from /usr/sbin/httpd
#13 0x00002b6d3f9a48a0 in ap_register_input_filter () from /usr/sbin/httpd
#14 0x00002b6d3f9a0a42 in ap_run_process_connection () from /usr/sbin/httpd
#15 0x00002b6d3f9ab22b in ap_graceful_stop_signalled () from /usr/sbin/httpd
#16 0x00002b6d3f9ab4ba in ap_graceful_stop_signalled () from /usr/sbin/httpd
#17 0x00002b6d3f9abd1d in ap_mpm_run () from /usr/sbin/httpd
#18 0x00002b6d3f986e04 

strace on parent httpd process:
select(0, NULL, NULL, NULL, {0, 707000}) = 0 (Timeout)
wait4(-1, 0x7fff1bbc933c, WNOHANG|WSTOPPED, NULL) = 0
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
wait4(-1, 0x7fff1bbc933c, WNOHANG|WSTOPPED, NULL) = 0
*snip snip*

strace on child httpd process (hung, all hung processes showed this):
Process 9648 attached - interrupt to quit
futex(0x2b19a0b01070, FUTEX_WAIT, 2, NULL) = -1 EINTR (Interrupted system call) 

(I believe the interrupted system call appeared when I restarted apache)

httpd -l output:
Compiled in modules:
  core.c
  prefork.c
  http_core.c
  mod_so.c

httpd -V
Server version: Apache/2.2.3
Server built:   Oct 28 2008 07:22:45
Server's Module Magic Number: 20051115:3
Server loaded:  APR 1.2.7, APR-Util 1.2.7
Compiled using: APR 1.2.7, APR-Util 1.2.7
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
 -D APACHE_MPM_DIR="server/mpm/prefork"
 -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
 -D HTTPD_ROOT="/etc/httpd"
 -D SUEXEC_BIN="/usr/sbin/suexec"
 -D DEFAULT_PIDLOG="logs/httpd.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_LOCKFILE="logs/accept.lock"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="conf/mime.types"
 -D SERVER_CONFIG_FILE="conf/httpd.conf"


ldd /usr/sbin/httpd
	libm.so.6 => /lib64/libm.so.6 (0x00002b1e7ada9000)
	libpcre.so.0 => /lib64/libpcre.so.0 (0x00002b1e7b02c000)
	libselinux.so.1 => /lib64/libselinux.so.1 (0x00002b1e7b248000)
	libaprutil-1.so.0 => /usr/lib64/libaprutil-1.so.0 (0x00002b1e7b461000)
	libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00002b1e7b67e000)
	libldap-2.3.so.0 => /usr/lib64/libldap-2.3.so.0 (0x00002b1e7b8b6000)
	liblber-2.3.so.0 => /usr/lib64/liblber-2.3.so.0 (0x00002b1e7baf1000)
	libdb-4.3.so => /lib64/libdb-4.3.so (0x00002b1e7bcff000)
	libexpat.so.0 => /lib64/libexpat.so.0 (0x00002b1e7bff4000)
	libapr-1.so.0 => /usr/lib64/libapr-1.so.0 (0x00002b1e7c217000)
	libpthread.so.0 => /lib64/libpthread.so.0 (0x00002b1e7c43e000)
	libdl.so.2 => /lib64/libdl.so.2 (0x00002b1e7c658000)
	libc.so.6 => /lib64/libc.so.6 (0x00002b1e7c85d000)
	libsepol.so.1 => /lib64/libsepol.so.1 (0x00002b1e7cbb0000)
	/lib64/ld-linux-x86-64.so.2 (0x00002b1e7ab8d000)
	libuuid.so.1 => /lib64/libuuid.so.1 (0x00002b1e7cdf6000)
	libpq.so.4 => /usr/lib64/libpq.so.4 (0x00002b1e7cffb000)
	libsqlite3.so.0 => /usr/lib64/libsqlite3.so.0 (0x00002b1e7d21d000)
	libresolv.so.2 => /lib64/libresolv.so.2 (0x00002b1e7d477000)
	libsasl2.so.2 => /usr/lib64/libsasl2.so.2 (0x00002b1e7d68d000)
	libssl.so.6 => /lib64/libssl.so.6 (0x00002b1e7d8a6000)
	libcrypto.so.6 => /lib64/libcrypto.so.6 (0x00002b1e7daef000)
	libkrb5.so.3 => /usr/lib64/libkrb5.so.3 (0x00002b1e7de38000)
	libnsl.so.1 => /lib64/libnsl.so.1 (0x00002b1e7e0cb000)
	libgssapi_krb5.so.2 => /usr/lib64/libgssapi_krb5.so.2 (0x00002b1e7e2e4000)
	libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00002b1e7e512000)
	libk5crypto.so.3 => /usr/lib64/libk5crypto.so.3 (0x00002b1e7e714000)
	libz.so.1 => /usr/lib64/libz.so.1 (0x00002b1e7e93a000)
	libkrb5support.so.0 => /usr/lib64/libkrb5support.so.0 (0x00002b1e7eb4e000)
	libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00002b1e7ed56000)

ldd /usr/lib64/php/modules/apc.so.orig 
	librt.so.1 => /lib64/librt.so.1 (0x00002ad3557fb000)
	libc.so.6 => /lib64/libc.so.6 (0x00002ad355a04000)
	libpthread.so.0 => /lib64/libpthread.so.0 (0x00002ad355d57000)
	/lib64/ld-linux-x86-64.so.2 (0x00000033a8c00000)

Linux 2.6.18-92.1.6.el5 #1 SMP Fri Jun 20 02:36:06 EDT 2008 x86_64 x86_64 x86_64 GNU/Linux

cat /etc/php.d/apc.ini 
extension=apc.so
apc.enabled=1
apc.shm_segments=1
apc.shm_size=128
apc.ttl=7200
apc.user_ttl=7200
apc.num_files_hint=1024
apc.mmap_file_mask=/tmp/apc.XXXXXX
apc.enable_cli=1

cat /proc/sys/kernel/shmmax
68719476736

free -m
             total       used       free     shared    buffers     cached
Mem:         16121      14696       1425          0        331      11649
-/+ buffers/cache:       2715      13406
Swap:         1992         20       1972

php -m
[PHP Modules]
apc
bz2
calendar
ctype
curl
date
dbase
dom
exif
ftp
gd
gettext
gmp
hash
iconv
imap
libxml
mbstring
mime_magic
mysql
mysqli
openssl
pcntl
pcre
PDO
pdo_mysql
pdo_sqlite
posix
pspell
Reflection
session
shmop
SimpleXML
sockets
SPL
standard
sysvmsg
sysvsem
sysvshm
tokenizer
wddx
xml
xmlreader
xmlwriter
xsl
zlib

[Zend Modules]

----------

I can not provide code, unfortunately, nor do I know where in the code base this issue occurs. One point of reference, shm_size was increased to 512, and the issue still occurred. Due to the nature of this issue on a production server, it is very difficult to re-enable APC to test further. If I can provide any more information to be of assistance, please feel free to contact me at any time.


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2008-12-04 09:55 UTC] ormandj at gmail dot com
Resolved.
 [2009-01-11 15:25 UTC] ormandj at gmail dot com
For those encountering this issue, please upgrade to APC >=3.1.x.
 [2011-01-28 04:22 UTC] mark at hell dot ne dot jp
Hi,

I have this exact same problem with APC 3.1.4

I have upgraded to 3.1.7 hoping this will solve the issue, 
however I couldn't find anything in the changelog. I'll post 
the backtrace here just in case:

#0  0x00007fb9167f2044 in __lll_lock_wait () from 
/lib/libpthread.so.0
#1  0x00007fb9167ed349 in _L_lock_534 () from 
/lib/libpthread.so.0
#2  0x00007fb9167ed15e in pthread_mutex_lock () from 
/lib/libpthread.so.0
#3  0x00007fb90f65dc49 in apc_pthreadmutex_lock 
(lock=0x7fb8ccf76088) at /usr/src/php-web-5.3.3/mod/APC-
3.1.4/apc_pthreadmutex.c:72
#4  0x00007fb90f65856e in apc_cache_find_slot 
(cache=0xb5fb20, key=..., t=1296204433) at /usr/src/php-web-
5.3.3/mod/APC-3.1.4/apc_cache.c:578
#5  0x00007fb90f658a04 in apc_cache_find 
(cache=0x7fb8ccf76088, key=..., t=0) at /usr/src/php-web-
5.3.3/mod/APC-3.1.4/apc_cache.c:626
#6  0x00007fb90f65d279 in my_compile_file (h=0x7fff6cba9ad0, 
type=8) at /usr/src/php-web-5.3.3/mod/APC-
3.1.4/apc_main.c:547
#7  0x00007fb915806079 in phar_compile_file 
(file_handle=0x7fff6cba9ad0, type=8) at /usr/src/php-web-
5.3.3/ext/phar/phar.c:3393
#8  0x00007fb9159b36d1 in zend_execute_scripts (type=8, 
retval=0x0, file_count=3) at /usr/src/php-web-
5.3.3/Zend/zend.c:1186
#9  0x00007fb91595f2b8 in php_execute_script 
(primary_file=0x7fff6cba9ad0) at /usr/src/php-web-
5.3.3/main/main.c:2260
#10 0x00007fb915a3e62f in php_handler (r=0xc5e9f0) at 
/usr/src/php-web-
5.3.3/sapi/apache2handler/sapi_apache2.c:669
#11 0x0000000000446603 in ap_run_handler (r=0xc5e9f0) at 
config.c:158
#12 0x0000000000449b36 in ap_invoke_handler (r=0xc5e9f0) at 
config.c:376
#13 0x0000000000494210 in ap_internal_redirect (new_uri=
<value optimized out>, r=<value optimized out>) at 
http_request.c:502
#14 0x00000000004bfb29 in handler_redirect (r=0xc4f2d0) at 
mod_rewrite.c:4831
#15 0x0000000000446603 in ap_run_handler (r=0xc4f2d0) at 
config.c:158
#16 0x0000000000449b36 in ap_invoke_handler (r=0xc4f2d0) at 
config.c:376
#17 0x00000000004943a8 in ap_process_request (r=0xc4f2d0) at 
http_request.c:282
#18 0x0000000000491488 in ap_process_http_connection 
(c=0xc41120) at http_core.c:190
#19 0x000000000044daf3 in ap_run_process_connection 
(c=0xc41120) at connection.c:43
#20 0x00000000004c367b in child_main (child_num_arg=<value 
optimized out>) at prefork.c:662
#21 0x00000000004c3944 in make_child (s=0x7285b0, slot=230) 
at prefork.c:758
#22 0x00000000004c455e in perform_idle_server_maintenance 
(_pconf=<value optimized out>, plog=<value optimized out>, 
s=<value optimized out>) at prefork.c:893
#23 ap_mpm_run (_pconf=<value optimized out>, plog=<value 
optimized out>, s=<value optimized out>) at prefork.c:1097
#24 0x00000000004332c5 in main (argc=3, argv=0x7fff6cbaa148) 
at main.c:740
 [2011-02-14 18:20 UTC] chris at ocproducts dot com
I get this on 3.1.6.

It's been happening many times for me, I only just tracked 
it down via gdb...


#0  __lll_lock_wait () at 
../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:136
#1  0x00007f07a92d4065 in _L_lock_868 () from 
/lib64/libpthread.so.0
#2  0x00007f07a92d3f37 in __pthread_mutex_lock 
(mutex=0x7f078735f088) at pthread_mutex_lock.c:61
#3  0x00007f07a252b4d9 in apc_pthreadmutex_lock (lock=<value 
optimized out>) at /root/APC-3.1.6/apc_pthreadmutex.c:72
#4  0x00007f07a2525e26 in apc_cache_find_slot 
(cache=0x7f07ab825190, key=Asked for position 0 of stack, 
stack only has 0 elements on it.) at /root/APC-
3.1.6/apc_cache.c:598
#5  0x00007f07a2526284 in apc_cache_find (cache=<value 
optimized out>, key=..., t=<value optimized out>) at 
/root/APC-3.1.6/apc_cache.c:646
#6  0x00007f07a252a691 in my_compile_file (h=0x7fffc8d741b0, 
type=8) at /root/APC-3.1.6/apc_main.c:525
#7  0x00007f079ef27711 in ?? () from 
/usr/lib64/php/modules/phar.so
#8  0x00007f07a333420a in zend_execute_scripts () from 
/etc/httpd/modules/libphp5.so
#9  0x00007f07a32e2548 in php_execute_script () from 
/etc/httpd/modules/libphp5.so
#10 0x00007f07a33bd125 in ?? () from 
/etc/httpd/modules/libphp5.so
#11 0x00007f07aaa246f0 in ap_run_handler ()

My characterisation of problem: the server is asked for a 
certain page and APC 'compiles' it, and then randomly that 
process makes APC crash. Anything else trying to access that 
page is waiting for the APC lock on that page to be freed 
(and it never will, the process crashed). Eventually a few 
hours later all the available slots for serving web pages 
are left waiting for the lock to be freed.

I have changed to file locks, not sure if that will help, 
but at least is easier to debug.

I have turned on core dumps so I will post if I get an APC 
core dump happening now.
 [2011-02-14 18:25 UTC] rasmus@php.net
Well, with file locks you wouldn't get stuck in a 
pthread_mutex lock so it should be very different.

Try pthread rw locking as well.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Sat Apr 20 05:01:27 2024 UTC