Bug 53999 - Deadlock between procmgr_send_spawn_cmd()/proctable_lock() in mod_fcgid and listener_thread() in worker_mpm
Summary: Deadlock between procmgr_send_spawn_cmd()/proctable_lock() in mod_fcgid and l...
Status: REOPENED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_fcgid (show other bugs)
Version: 2.4.4
Hardware: PC Linux
: P2 normal with 6 votes (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-10-13 01:30 UTC by Bartosz Kwitniewski
Modified: 2017-03-02 11:17 UTC (History)
2 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Bartosz Kwitniewski 2012-10-13 01:30:50 UTC
Hello!

I would like to merge servers from Apache 2.2 to 2.4 but a deadlock that was quite rare in 2.2 makes 2.4 unusable. It is between listener_thread() in worker_mpm and at least these mod_fcgid functions: procmgr_send_spawn_cmd()/proctable_lock()/proctable_pm_lock(). In Apache 2.2 it occured only under heavy load while in 2.4 it occurs within few minutes, up to half hour after server start, even under low server load.

Deadlock results in httpd process terminating itself and leaving many fcgid processes in busy state that never changes to idle. Busy processes turn into zombies after some time (possibly after process_kill_gracefully()) so process_kill_gracefully()/process_kill_force() in scan_busylist() is unable to kill them and since they are on busy list they are never collected by scan_idlelist_zombie(). The final result is full saturation of FcgidMaxProcessesPerClass limit by zombies for some VirtualHosts which in turn results in permanent 503 error until whole serwer is restarted (can be graceful).

I am able to reproduce problem on machine with 2 processors by creating 5 VirtualHosts pointing to a separate Joomla installations and then executing the following test on all VirtualHosts simultaneously:

ab -n 10000 -c 10 vhostX/

Example MPM/mod_fcgid configuration triggering deadlock:

<IfModule worker.c>
    ServerLimit                  3
    ThreadLimit                100
    StartServers                 1
    MaxClients                 300
    MinSpareThreads             50
    MaxSpareThreads            175
    ThreadsPerChild            100
    MaxConnectionsPerChild  100000
</IfModule>
<IfModule mod_fcgid.c>
   FcgidMaxProcesses 400
   FcgidMinProcessesPerClass 0
   FcgidMaxProcessesPerClass 5
   FcgidMaxRequestsPerProcess 500
   FcgidInitialEnv PHP_FCGI_MAX_REQUESTS 500
   FcgidProcessLifeTime 135
   FcgidSpawnScore 1
   FcgidTerminationScore 1
   FcgidTimeScore 100
   FcgidSpawnScoreUpLimit 100
   FcgidIOTimeout 65
   FcgidIdleTimeout 60
   FcgidIdleScanInterval 30
   FcgidBusyTimeout 65
   FcgidBusyScanInterval 60
</IfModule>

System: Debian 6.0.x 64 bit
Apache: 2.4.3
mod_fcgid: SVN rev. 1397462 (bug also present in 2.3.7 and 2.3.6)
Compilation flags: -O0 -ggdb

Deadlock is usually triggered within 5 minutes after starting ab.

----------[ Debug info from deadlock on the worker_mpm side ]----------
Error in logfile:

[mpm_worker:emerg] [pid 13326:tid 139649122420480] (35)Resource deadlock avoided: AH00273: apr_proc_mutex_lock failed. Attempting to shutdown process gracefully.

Deadlock in listener_thread() at worker.c:762:

        /* We've already decremented the idle worker count inside                                                                                            
         * ap_queue_info_wait_for_idler. */

====>   if ((rv = SAFE_ACCEPT(apr_proc_mutex_lock(accept_mutex)))
            != APR_SUCCESS) {

            if (!listener_may_exit) {
                accept_mutex_error("lock", rv, process_slot);
            }
            break;                    /* skip the lock release */
        }

Backtrace:

#0  0x00007f5003d9f45c in __pthread_kill (threadid=<value optimized out>, signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  0x000000000047bf64 in wakeup_listener () at worker.c:287
#2  0x000000000047bf97 in signal_threads (mode=1) at worker.c:310
#3  0x000000000047cd7c in accept_mutex_error (func=0x4929b8 "lock", rv=35, process_slot=0) at worker.c:678
#4  0x000000000047d0b8 in listener_thread (thd=0x21ccb18, dummy=0x209b290) at worker.c:766
#5  0x00007f5003fdbc03 in ?? () from /usr/lib/libapr-1.so.0
#6  0x00007f5003d998ca in start_thread (arg=<value optimized out>) at pthread_create.c:300
#7  0x00007f5003b0092d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#8  0x0000000000000000 in ?? ()

Local variables:

ti = 0x209b290
process_slot = 0
tpool = 0x21edb18
csd = 0x7f4fc4086d30
ptrans = 0x7f4fc4018a68
pollset = 0x21edb90
rv = 35                  <=== EDEADLK
lr = 0x1e97178
have_idle_worker = 1
last_poll_idx = 1

----------[ Debug info from deadlock on the mod_fcgid side ]----------
Error in logfile:

[fcgid:emerg] [pid 11624:tid 139810533033728] (35)Resource deadlock avoided: [client x.x.x.x:49337] mod_fcgid: can't get pipe mutex

There is also another one in proctable_lock()/proctable_pm_lock() but it is quite rare and I didn't get backtrace from it:

[fcgid:emerg] [pid 27202:tid 140334891595520] (35)Resource deadlock avoided: [client x.x.x.x:33273] mod_fcgid: can't lock process table in pid 27202

Deadlock in procmgr_send_spawn_cmd() at fcgid_pm_unix.c:467:

         /* Get the global mutex before posting the request */
====>    if ((rv = apr_global_mutex_lock(g_pipelock)) != APR_SUCCESS) {
             ap_log_rerror(APLOG_MARK, APLOG_EMERG, rv, r,
                           "mod_fcgid: can't get pipe mutex");
             exit(0);
         }

Backtrace:
#0  procmgr_send_spawn_cmd (command=0x7f5311e0b520, r=0x1403738) at fcgid_pm_unix.c:468
#1  0x00007f532808082b in handle_request (r=0x1403738, role=1, cmd_conf=0x13fa380, output_brigade=0x1404f70) at fcgid_bridge.c:450
#2  0x00007f5328081769 in bridge_request (r=0x1403738, role=1, cmd_conf=0x13fa380) at fcgid_bridge.c:765
#3  0x00007f532807df92 in fcgid_handler (r=0x1403738) at mod_fcgid.c:290
#4  0x000000000045662b in ap_run_handler (r=0x1403738) at config.c:169
#5  0x0000000000456f0b in ap_invoke_handler (r=0x1403738) at config.c:432
#6  0x0000000000473963 in ap_internal_redirect_handler (new_uri=0x1403718 "/cgi-bin/php-fcgi/index.php", r=0x1576880) at http_request.c:669
#7  0x00007f53288ad394 in action_handler (r=0x1576880) at mod_actions.c:205
#8  0x000000000045662b in ap_run_handler (r=0x1576880) at config.c:169
#9  0x0000000000456f0b in ap_invoke_handler (r=0x1576880) at config.c:432
#10 0x00000000004727b3 in ap_process_async_request (r=0x1576880) at http_request.c:317
#11 0x0000000000472899 in ap_process_request (r=0x1576880) at http_request.c:363
#12 0x000000000046ed81 in ap_process_http_sync_connection (c=0x13ef3b8) at http_core.c:190
#13 0x000000000046ee97 in ap_process_http_connection (c=0x13ef3b8) at http_core.c:231
#14 0x0000000000463bf2 in ap_run_process_connection (c=0x13ef3b8) at connection.c:41
#15 0x00000000004640bf in ap_process_connection (c=0x13ef3b8, csd=0x13ef1a0) at connection.c:202
#16 0x000000000047ca2c in process_socket (thd=0x1099478, p=0x13ef118, sock=0x13ef1a0, my_child_num=1, my_thread_num=42, bucket_alloc=0x13f1128)
    at worker.c:620
#17 0x000000000047d8a9 in worker_thread (thd=0x1099478, dummy=0x12056b0) at worker.c:979
#18 0x00007f532dfc4c03 in ?? () from /usr/lib/libapr-1.so.0
#19 0x00007f532dd828ca in start_thread (arg=<value optimized out>) at pthread_create.c:300
#20 0x00007f532dae992d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#21 0x0000000000000000 in ?? ()

Local variables:

rv = 35                <=== EDEADLK
result = 0
notifybyte = 0 '\000'
nbytes = 13160


procmgr_send_spawn_cmd() executes exit(0) on error when trying to lock mutex - shouldn't it return status code that indicates error? There is also lack of information that httpd process is actually terminated - "mod_fcgid: can't get pipe mutex" in logs does not look too harmful except for the emerg level.

Should I fill separate bug report for busy zombies not being collected?
Comment 1 Bartosz Kwitniewski 2013-05-14 22:40:58 UTC
I was unable to reproduce this bug with event MPM using unencrypted connections but it is still present when using SSL, probably due to this: "For SSL connections, this MPM will fall back to the behaviour of the worker MPM and reserve one worker thread per connection."
Comment 2 Bartosz Kwitniewski 2014-12-10 23:25:40 UTC
I'm unable to reproduce error on Linux 3.16.6 and Apache 2.4.10 anymore. I have received report that kernel upgrade in itself can fix this bug. Closing.
Comment 3 thomas 2015-08-20 14:58:44 UTC
Unfortunately I am able to reproduce the problem with a Debian Jessie installation.

Using mpm_worker and mod_fcgid the following messages begin to appear in the error log under heavy load (also triggerable via ab -c15):

[Mon Aug 17 15:21:13.509763 2015] [fcgid:emerg] [pid 21497:tid 139901035079424] (35)Resource deadlock avoided: [client XXX.XXX.XXX.XXX:38964] mod_fcgid: can't get pipe mutex
[...]
[Mon Aug 17 15:22:49.387129 2015] [fcgid:emerg] [pid 22016:tid 139900959545088] (35)Resource deadlock avoided: [client XXX.XXX.XXX.XXX:39590] mod_fcgid: can't lock process table in pid 22016
[Mon Aug 17 15:22:53.479254 2015] [fcgid:emerg] [pid 22047:tid 139901035079424] (35)Resource deadlock avoided: [client XXX.XXX.XXX.XXX:39617] mod_fcgid: can't lock process table in pid 22047
[...]


At the same time, gracefully terminated FCGI processes don't get wait()/waitpid() ed and are left in a zombie state by Apache until FcgidMaxProcessesPerClass are used up (then 503 errors).

Using mpm_event I was also able to reproduce the problem, however, the frequency was greatly reduced.

The only solution for me up to this point is using mpm_prefork, with which the error is not reproductible at all.

Apache version: 2.4.10
mod_fcgid version: 2.3.9
Linux kernel version: 3.16.7
Comment 4 Andreas 2015-09-03 17:13:43 UTC
Unfortunately I can confirm this problem with another Debian Jessie installation.

When using mpm_worker OR mpm_event and mod_fcgid i observed the same things as Thomas and could also resolve them by switching to mpm_prefork.

Apache version: 2.4.10-10+deb8u1
mod_fcgid version: 2.3.9-1+b1
Linux kernel version: 3.16.7-ckt11-1+deb8u3
PHP versions: 5.6.12+dfsg-0+deb8u1, self-compiled 5.5.28, self-compiled 5.6.12
Comment 5 Peter Blokland 2015-10-02 09:04:13 UTC
Another Debian Jessie user chiming in. I'm seeing this error too, but I'm not using mod_fcgi, but mod_fastcgi (which communicates via sockets with php-fpm):

[Fri Oct 02 06:40:08.558059 2015] [mpm_worker:notice] [pid 29795:tid 140436668389248] AH00292: Apache/2.4.10 (Debian) mod_fastcgi/mod_fastcgi-SNAP-0910052141 mod_jk/1.2.37 OpenSSL/1.0.1k configured -- resuming normal operations
[Fri Oct 02 06:40:08.558084 2015] [core:notice] [pid 29795:tid 140436668389248] AH00094: Command line: '/usr/sbin/apache2'
[Fri Oct 02 08:06:43.819080 2015] [mpm_worker:emerg] [pid 10105:tid 140436228171520] (35)Resource deadlock avoided: AH00273: apr_proc_mutex_lock failed. Attempting to shutdown process gracefully.
[Fri Oct 02 08:26:34.332824 2015] [mpm_worker:emerg] [pid 12883:tid 140436228171520] (35)Resource deadlock avoided: AH00273: apr_proc_mutex_lock failed. Attempting to shutdown process gracefully.
[Fri Oct 02 10:06:00.666482 2015] [mpm_worker:emerg] [pid 25550:tid 140436228171520] (35)Resource deadlock avoided: AH00273: apr_proc_mutex_lock failed. Attempting to shutdown process gracefully.

we just switched this machine from prefork to worker to avoid an issue where mod_dbd would starve the database of connections.

apache2                               2.4.10-10+deb8u3
libapache2-mod-fastcgi                2.4.7~0910052141-1.1
libapache2-mod-jk                     1:1.2.37-4+deb8u1
php5-fpm                              5.6.13+dfsg-0+deb8u1  
linux-image-3.16.0-4-amd64            3.16.7-ckt11-1+deb8u4
Comment 6 Eric Covener 2015-10-02 12:28:04 UTC
did debian change to using fcntl by default? See this old thread, it seems unusable with multiple independent mutexes.

http://mail-archives.apache.org/mod_mbox/apr-dev/200708.mbox/%3C1404e5910708190828t42013548td1a0c14d5669259d@mail.gmail.com%3E
Comment 7 Harald Kapper 2016-04-13 23:07:26 UTC
well, another debian v8.4 in this case.

recently switched for performance reasons to mpm_worker, now back to mpm_prefork for the same reason (and yet as we're on dbd too this fills up db-connections):

apache2                        2.4.10-10+deb8u4            amd64
apache2-mpm-worker             2.4.10-10+deb8u4            amd64
php5-fpm                       5.6.19+dfsg-0+deb8u1        amd64

libapache2-mod-fastcgi         2.4.7~0910052141-1.1+deb8u1 amd64

Kernel is a bit different: 2.6.32-44-pve

any direction for debian build team to fix this would be highly appreciated.

thx
hk
Comment 8 thomas 2016-04-18 16:52:41 UTC
@Andreas,Peter,Harald: Can you reproduce the bug with 'Mutex sem' (or a flock/pthread mutex)?

Not using the default (file -> fcntl) Mutex seems to fix the issue for me, so Eric might be correct (even if the liked report seems to only mention Solaris).

If this is true, the Debian maintainer should be informed about this (and the default Mutex type should be changed to sem, pthread or flock) and this bug report may be closed.
Comment 9 David Martínez Martí 2016-09-02 06:49:42 UTC
Thomas, we were getting the same problem, and your comment helped a lot.

"Mutex sem" seems the solution.

Did two tests in siege using this command:
siege -f /tmp/urls.sort1.awk.txt -i -d0 -c20 -v | grep -vE "200   [01]"

I did only a change between first and second test: /etc/apache2/apache2.conf
# Mutex file:${APACHE_LOCK_DIR} default   # Original config (1st Test)
Mutex sem  # (Config 2nd test)


In the first siege test:
Transactions:                  32958 hits
Availability:                  99.43 %
Elapsed time:                 115.76 secs
Data transferred:              14.80 MB
Response time:                  0.07 secs
Transaction rate:             284.71 trans/sec
Throughput:                     0.13 MB/sec
Concurrency:                   19.42
Successful transactions:       32960
Failed transactions:             189
Longest transaction:            8.96
Shortest transaction:           0.00

In 115 seconds I had to stop because I got 115 PHP orphaned processes.

In the second siege test:
Transactions:                  99533 hits
Availability:                  99.98 %
Elapsed time:                 292.05 secs
Data transferred:              44.50 MB
Response time:                  0.05 secs
Transaction rate:             340.81 trans/sec
Throughput:                     0.15 MB/sec
Concurrency:                   17.80
Successful transactions:       99533
Failed transactions:              21
Longest transaction:           29.04
Shortest transaction:           0.00

After 5 minutes and 0 zombies and 0 orphaned processes.

As you can see it is slightly faster than the prior configuration. And 0.02% failure, which is 10x times less than before.

I'm using Debian Jessie, kernel 4.4.4-xxxx-grs-ipv6-64 #7 SMP x86_64 GNU/Linux
Comment 10 Bartosz Kwitniewski 2016-12-06 16:57:16 UTC
Just a note: if You have strange crashes/deadlocks while using "Mutex sem", then it might be related to semaphore arrays limit in the kernel, which is 128 by default. You can check semaphores currently used by Apache with "ipcs -s". Limit can be changed from 128 to e.g. 1024 using sysctl (last number is the limit):

sysctl -w kernel.sem="250 32000 32 1024"