ID: 26494 User updated by: hexer at studentcenter dot org Reported By: hexer at studentcenter dot org Status: Open Bug Type: Apache related Operating System: Linux PHP Version: 4.3.10 New Comment:
Update: More test results, some improvements to the patch. After some testing on our production cluster I've made some improvements on the patch. (Scroll down for the patch itself) For a better way on reproducing this, check out the newsgroups post that talks more about this problem: http://groups-beta.google.com/group/php.general/browse_frm/thread/f18f3da1cc3b51a7/1e7c60d14432f6c5?q=mod_php+timeout&_done=%2Fgroups%3Fq%3Dmod_php+timeout%26hl%3Den%26lr%3D%26sa%3DN%26tab%3Dwg%26&_doneTitle=Back+to+Search&&d#1e7c60d14432f6c5 (Reproducible with latest version of Apache 1.3 and php 4.3.10) THE PATCH: (mod_php) List of changes since the initial version of the patch: 1. hard_timeout is no longer set before the main entry into the php engine execution. (TimeOut must only be used to monitor for stalled client connections according to the apache spec) 2. fixed for proper use of apache timeout in the READ post section. (timer is now primed before the start the read loop, timer refreshes in between the reads and is killed after the read loop so that TimeOut is tracked during communication and refreshed accordingly. 3. changed to ap_soft_timeout in the ub_write section. This makes PHP's ignore_user_abort possible again. (ap_soft_timeout causes apache to close socket instead of forcing a quit) Our test results: Upon setting apache TimeOut to 60, the server closes the connection with the client if and only if the connection has been stalled for more than 60 seconds during transfers. Since long script execution times are not considered stalls, the server only primes TimeOut timer during non-I/O operations of php and "kills" it afterwards. In other words, a php page can run for more than TimeOut number of seconds until max_execution_time if it is doing something other than outputting to the client or transfering POST data. Performance analysis: We have been running the earlier version of this patch on our production servers since this bug was first opened for several months now. There has been no noticable performance penalty. This new version of the patch has been running for about a week. We suggest a more thorough testing just in case. Especially with stalled POST's because that was the new addition to this patch. NOTE: To replicate this problem you MUST simulate a connection stall before a php page finishes its output. Hitting the stop button on a browser is not sufficient. We had to literally unplug the client computer's ethernet connection immediately after request to a php page to test this. --- /usr/local/src/php-4.3.10/sapi/apache/mod_php4.c 2005-01-10 15:11:53.000000000 -0500 *************** *** 97,107 **** static int sapi_apache_ub_write(const char *str, uint str_length TSRMLS_DC) { int ret=0; if (SG(server_context)) { ! ret = rwrite(str, str_length, (request_rec *) SG(server_context)); } if (ret != str_length) { php_handle_aborted_connection(); } return ret; --- 97,109 ---- static int sapi_apache_ub_write(const char *str, uint str_length TSRMLS_DC) { int ret=0; if (SG(server_context)) { ! ap_soft_timeout("php send body", (request_rec *) SG(server_context)); ! ret = rwrite(str, str_length, (request_rec *) SG(server_context)); ! ap_kill_timeout((request_rec *) SG(server_context)); } if (ret != str_length) { php_handle_aborted_connection(); } return ret; *************** *** 139,157 **** if (!SG(read_post_bytes) && !ap_should_client_block(r)) { return total_read_bytes; } handler = signal(SIGPIPE, SIG_IGN); while (total_read_bytes<count_bytes) { - hard_timeout("Read POST information", r); /* start timeout timer */ read_bytes = get_client_block(r, buffer+total_read_bytes, count_bytes-total_read_bytes); ! reset_timeout(r); if (read_bytes<=0) { break; } total_read_bytes += read_bytes; } signal(SIGPIPE, handler); return total_read_bytes; } /* }}} */ --- 141,161 ---- if (!SG(read_post_bytes) && !ap_should_client_block(r)) { return total_read_bytes; } handler = signal(SIGPIPE, SIG_IGN); + + ap_hard_timeout("Read POST information", r); /* start timeout timer */ while (total_read_bytes<count_bytes) { read_bytes = get_client_block(r, buffer+total_read_bytes, count_bytes-total_read_bytes); ! ap_reset_timeout(r); if (read_bytes<=0) { break; } total_read_bytes += read_bytes; } + ap_kill_timeout(r); signal(SIGPIPE, handler); return total_read_bytes; } /* }}} */ *************** *** 606,617 **** } /* Assume output will be of the default MIME type. Individual scripts may change this later in the request. */ r->content_type = php_apache_get_default_mimetype(r TSRMLS_CC); - /* Init timeout */ - hard_timeout("send", r); SG(server_context) = r; php_save_umask(); add_common_vars(r); --- 610,619 ---- *************** *** 620,630 **** init_request_info(TSRMLS_C); apache_php_module_main(r, display_source_mode TSRMLS_CC); /* Done, restore umask, turn off timeout, close file and return */ php_restore_umask(); - kill_timeout(r); } zend_end_try(); return OK; } /* }}} */ --- 622,631 ---- Previous Comments: ------------------------------------------------------------------------ [2004-12-23 00:02:13] hexer at studentcenter dot org Note: The issue still persists in version 4.3.10 and all versions in between. ------------------------------------------------------------------------ [2004-12-22 23:59:06] hexer at studentcenter dot org Hi, For the impatient, I have included a patch to solve this issue below. We can't use the default installation of php on our site because the dead client connections can hang up to hours and god up the precious httpd slots, as well as keep database connections open in php pages that close them only at the end of execution. Read on for the explanation of what the patch does and why. Apparently mod_php does not correctly follow the apache's TimeOut specification. >From apache docs: The TimeOut directive currently defines the amount of time Apache will wait for three things: 1. The total amount of time it takes to receive a GET request. 2. The amount of time between receipt of TCP packets on a POST or PUT request. 3 .The amount of time between ACKs on transmissions of TCP packets in responses. The apache API provides a handful of functions that deal with tracking timeout they are: ap_hard_timeout(), ap_soft_timeout(), ap_reset_timeout() and ap_kill_timeout() The ap_hard_timeout() and soft_timeout starts or restarts countdown until the apache gets an ALRM letting it know that the TimeOut has been reached. ap_kill_timeout() will unset the timer and disable the timeout trigger from being received. There are two types of timeouts, hard and soft. Soft timeouts simply close the socket and let the module do the cleanup work while hard timeouts force things to exit less cleanly. Using hard timeouts in mod_php will break the php's ignore_user_abort option in certain scenarious (such as dead client) so we have to use soft timeouts. In the default php installation, mod_php calls hard_timeout() before the main entry point into the php engine. This implementation does not follow the apache's spec. Theoretically this would force a script to exit after TimeOut value has expired regardless of it's max_execution_time. But in practice this does not happen because TimeOut signal framework is broken somewhere along the php execution. What we need is a change to the implementation so that apache only gets set to timeout between sends to the client but not during other php executions. The way it is done in this patch is by setting the timer before the sends, then unsetting the timer at the end of sends so that the server does not get a timeout during the portions of the script execution where no output is sent to the client. A good way to test compliance to the TimeOut, ignore_user_abort and max_execution_time is to make a test script that prints something out, sleeps for > TimeOut seconds, prints something else, etc. If the module is compliant it should: 1. detect dead connection and close it 2. ignore TimeOut during execution of non output-related instructions 3. exit after max_execution_time 4. continue execution after connection is closed if ignore_user_abort option is set. The following patch fixes TimeOut and makes mod_php compliant with apache's description. It has been tested on a server with average traffic of 64 requests/sec. We've been using this patch for a few months without any noticable performance impact. Tested with php 4.3.10 compiled-in with apache 1.3.33 Our conf string for php: ./configure --with-mysql \ --with-xml \ --with-apache=../apache_1.3.33 \ --enable-track-vars \ --with-gd \ --enable-discard-path \ --enable-bcmath \ --enable-gd-native-tt \ --with-freetype-dir=/usr/local \ --with-png-dir=/usr/local \ --with-jpeg-dir=/usr/local \ --with-zlib=/usr/local \ --enable-apc Conf string for apache: ./configure \ --activate-module=src/modules/php4/libphp4.a \ --enable-module=php4 \ --enable-module=rewrite \ --enable-module=so \ --prefix=/usr/local/apache --- mod_php4.c 2004-07-21 12:25:28.000000000 -0400 +++ /usr/local/src/php-4.3.10/sapi/apache/mod_php4.c 2004-12-22 16:57:43.000000000 -0500 @@ -99,7 +99,9 @@ int ret=0; if (SG(server_context)) { - ret = rwrite(str, str_length, (request_rec *) SG(server_context)); + ap_soft_timeout("php send body", (request_rec *) SG(server_context)); + ret = rwrite(str, str_length, (request_rec *) SG(server_context)); + ap_kill_timeout((request_rec *) SG(server_context)); } if (ret != str_length) { php_handle_aborted_connection(); @@ -142,9 +144,9 @@ handler = signal(SIGPIPE, SIG_IGN); while (total_read_bytes<count_bytes) { - hard_timeout("Read POST information", r); /* start timeout timer */ + ap_hard_timeout("Read POST information", r); /* start timeout timer */ read_bytes = get_client_block(r, buffer+total_read_bytes, count_bytes-total_read_bytes); - reset_timeout(r); + ap_kill_timeout(r); if (read_bytes<=0) { break; } @@ -608,8 +610,6 @@ scripts may change this later in the request. */ r->content_type = php_apache_get_default_mimetype(r TSRMLS_CC); - /* Init timeout */ - hard_timeout("send", r); SG(server_context) = r; @@ -622,7 +622,6 @@ /* Done, restore umask, turn off timeout, close file and return */ php_restore_umask(); - kill_timeout(r); } zend_end_try(); return OK; ------------------------------------------------------------------------ [2003-12-02 21:52:43] [EMAIL PROTECTED] I am having some difficulty replacating the problem and have not been able to get it to happen YET. Meanwhile could you please see if the problem occurs with PHP is compiled with mysql support? ------------------------------------------------------------------------ [2003-12-02 15:06:49] hexer at studentcenter dot org it seems that somewhere along the line, SIG_ALRM handler gets rerouted or disabled in one of the php extensions (I'm highly suspecting mysql) since apache's timeout relies on SIG_ALRM anything within php that disables it will break the timeout mechanism. The stuck processes abort normally when calling the handler directly from GDB, however when receiving SIG_ALRM nothing happens. the following is the config string for php ./configure --with-mysql \ --with-xml \ --with-apache=../apache_1.3.29 \ --enable-track-vars \ --with-gd \ --enable-discard-path \ --enable-bcmath \ --enable-gd-native-tt \ --with-freetype-dir=/usr/local \ --with-png-dir=/usr/local \ --with-jpeg-dir=/usr/local \ --with-zlib=/usr/local \ --enable-apc from all the included extensions mysql seems to be the only one with references to SIG_ALRM. I will continue looking but currently the only solution that worked for me is setting the timeout on send's. please let me know if you were able to reproduce this. ------------------------------------------------------------------------ [2003-12-02 13:22:07] [EMAIL PROTECTED] The timeouts are already being set around the entire PHP processing block look at mod_php4.c line 611 and lower. You suggestion would force a timeout setting around every single write, making things extremely slow, current code already should handle the situation you describe. ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/26494 -- Edit this bug report at http://bugs.php.net/?id=26494&edit=1
