FastCGI/PHP strange behavior on high load (Trac #191)

[edsiper]

When doing some benchmarks over the FastCGI interface with a PHP-FPM backend, the tool (client) doing the benchmark hangs as waiting for some pending information.

This is not easy to reproduce, but a simple test like this can be done:

weighttp -n 500 -c 8 -k http://localhost:2001/test.php

where test.php is a simple script that returns a short "Hello World!" message.

Looking at the final trace of the server we have the following:

~ 79.558423 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300
~ 79.558460 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT
~ 79.558498 [core|mk_epoll.c:359] mk_epoll_del(): [FD 23] Epoll, remove from QUEUE_FD=5
~ 79.558537 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 23] Scheduler remove
~ 79.558579 [core|mk_plugin.c:886] mk_plugin_http_request_end(): [FD 27] PLUGIN HTTP REQUEST END
~ 79.558597 [core|mk_request.c:921] mk_request_free_list(): [FD 27] Free struct client_session
~ 79.558606 [core|mk_plugin.c:886] mk_plugin_http_request_end(): [FD 21] PLUGIN HTTP REQUEST END
~ 79.558645 [core|mk_request.c:921] mk_request_free_list(): [FD 21] Free struct client_session
~ 79.558670 [core|mk_epoll.c:385] mk_epoll_change_mode(): [FD 21] EPoll changing mode to READ
~ 79.558697 [core|mk_plugin.c:901] mk_plugin_http_request_end(): ret = 0
~ 79.558728 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'write' returned -400
~ 79.558754 [core|mk_plugin.c:988] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_OWNED
~ 79.558783 [core|mk_epoll.c:265] mk_epoll_init(): [FD 21] EPoll Event READ
~ 79.558808 [core|mk_connection.c:33] mk_conn_read(): [FD 21] Connection Handler / read
~ 79.558833 [core|mk_plugin.c:1022] mk_plugin_event_read(): [FD 21] Read Event
~ 79.558860 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'read' returned -300
~ 79.558885 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT
~ 79.558910 [core|mk_request.c:621] mk_handler_read(): MAX REQUEST SIZE: 32768
~ 79.558939 [core|mk_request.c:663] mk_handler_read(): [FD 21] read 0
~ 79.558967 [core|mk_epoll.c:298] mk_epoll_init(): [FD 21] Epoll Event FORCE CLOSE | ret = -1
~ 79.558996 [core|mk_connection.c:208] mk_conn_close(): [FD 21] Connection Handler, closed
~ 79.559021 [core|mk_plugin.c:1160] mk_plugin_event_close(): [FD 21] Plugin event close
~ 79.559047 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300
~ 79.559072 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT
~ 79.559099 [core|mk_epoll.c:359] mk_epoll_del(): [FD 21] Epoll, remove from QUEUE_FD=6
~ 79.559128 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 21] Scheduler remove
~ 79.559163 [core|mk_epoll.c:385] mk_epoll_change_mode(): [FD 27] EPoll changing mode to READ
~ 79.559179 [core|mk_plugin.c:901] mk_plugin_http_request_end(): ret = 0
~ 79.559187 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'write' returned -400
~ 79.559194 [core|mk_plugin.c:988] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_OWNED
~ 79.559204 [core|mk_epoll.c:265] mk_epoll_init(): [FD 27] EPoll Event READ
~ 79.559212 [core|mk_connection.c:33] mk_conn_read(): [FD 27] Connection Handler / read
~ 79.559219 [core|mk_plugin.c:1022] mk_plugin_event_read(): [FD 27] Read Event
~ 79.559228 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'read' returned -300
~ 79.559235 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT
~ 79.559242 [core|mk_request.c:621] mk_handler_read(): MAX REQUEST SIZE: 32768
~ 79.559253 [core|mk_request.c:663] mk_handler_read(): [FD 27] read 0
~ 79.559261 [core|mk_epoll.c:298] mk_epoll_init(): [FD 27] Epoll Event FORCE CLOSE | ret = -1
~ 79.559269 [core|mk_connection.c:208] mk_conn_close(): [FD 27] Connection Handler, closed
~ 79.559276 [core|mk_plugin.c:1160] mk_plugin_event_close(): [FD 27] Plugin event close
~ 79.559284 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300
~ 79.559292 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT
~ 79.559301 [core|mk_epoll.c:359] mk_epoll_del(): [FD 27] Epoll, remove from QUEUE_FD=9
~ 79.559309 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 27] Scheduler remove

there is nothing pending, looks like the server serve everything but weighttp is still waiting for something more, the same behavior can be seen with apache-benchmark tool (ab).

Migrated from http://bugs.monkey-project.com/ticket/191

{
    "status": "new", 
    "changetime": "2013-12-30T23:01:11", 
    "description": "When doing some benchmarks over the FastCGI interface with a PHP-FPM backend, the tool (client) doing the benchmark hangs as waiting for some pending information.\n\nThis is not easy to reproduce, but a simple test like this can be done:\n\n   weighttp -n 500 -c 8 -k http://localhost:2001/test.php\n\nwhere test.php is a simple script that returns a short \"Hello World!\" message.\n\nLooking at the final trace of the server we have the following:\n\n~ 79.558423 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300\n~ 79.558460 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT\n~ 79.558498 [core|mk_epoll.c:359] mk_epoll_del(): [FD 23] Epoll, remove from QUEUE_FD=5\n~ 79.558537 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 23] Scheduler remove\n~ 79.558579 [core|mk_plugin.c:886] mk_plugin_http_request_end(): [FD 27] PLUGIN HTTP REQUEST END\n~ 79.558597 [core|mk_request.c:921] mk_request_free_list(): [FD 27] Free struct client_session\n~ 79.558606 [core|mk_plugin.c:886] mk_plugin_http_request_end(): [FD 21] PLUGIN HTTP REQUEST END\n~ 79.558645 [core|mk_request.c:921] mk_request_free_list(): [FD 21] Free struct client_session\n~ 79.558670 [core|mk_epoll.c:385] mk_epoll_change_mode(): [FD 21] EPoll changing mode to READ\n~ 79.558697 [core|mk_plugin.c:901] mk_plugin_http_request_end():  ret = 0\n~ 79.558728 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'write' returned -400\n~ 79.558754 [core|mk_plugin.c:988] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_OWNED\n~ 79.558783 [core|mk_epoll.c:265] mk_epoll_init(): [FD 21] EPoll Event READ\n~ 79.558808 [core|mk_connection.c:33] mk_conn_read(): [FD 21] Connection Handler / read\n~ 79.558833 [core|mk_plugin.c:1022] mk_plugin_event_read(): [FD 21] Read Event\n~ 79.558860 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'read' returned -300\n~ 79.558885 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT\n~ 79.558910 [core|mk_request.c:621] mk_handler_read(): MAX REQUEST SIZE: 32768\n~ 79.558939 [core|mk_request.c:663] mk_handler_read(): [FD 21] read 0\n~ 79.558967 [core|mk_epoll.c:298] mk_epoll_init(): [FD 21] Epoll Event FORCE CLOSE | ret = -1\n~ 79.558996 [core|mk_connection.c:208] mk_conn_close(): [FD 21] Connection Handler, closed\n~ 79.559021 [core|mk_plugin.c:1160] mk_plugin_event_close(): [FD 21] Plugin event close\n~ 79.559047 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300\n~ 79.559072 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT\n~ 79.559099 [core|mk_epoll.c:359] mk_epoll_del(): [FD 21] Epoll, remove from QUEUE_FD=6\n~ 79.559128 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 21] Scheduler remove\n~ 79.559163 [core|mk_epoll.c:385] mk_epoll_change_mode(): [FD 27] EPoll changing mode to READ\n~ 79.559179 [core|mk_plugin.c:901] mk_plugin_http_request_end():  ret = 0\n~ 79.559187 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'write' returned -400\n~ 79.559194 [core|mk_plugin.c:988] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_OWNED\n~ 79.559204 [core|mk_epoll.c:265] mk_epoll_init(): [FD 27] EPoll Event READ\n~ 79.559212 [core|mk_connection.c:33] mk_conn_read(): [FD 27] Connection Handler / read\n~ 79.559219 [core|mk_plugin.c:1022] mk_plugin_event_read(): [FD 27] Read Event\n~ 79.559228 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'read' returned -300\n~ 79.559235 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT\n~ 79.559242 [core|mk_request.c:621] mk_handler_read(): MAX REQUEST SIZE: 32768\n~ 79.559253 [core|mk_request.c:663] mk_handler_read(): [FD 27] read 0\n~ 79.559261 [core|mk_epoll.c:298] mk_epoll_init(): [FD 27] Epoll Event FORCE CLOSE | ret = -1\n~ 79.559269 [core|mk_connection.c:208] mk_conn_close(): [FD 27] Connection Handler, closed\n~ 79.559276 [core|mk_plugin.c:1160] mk_plugin_event_close(): [FD 27] Plugin event close\n~ 79.559284 [core|mk_plugin.c:982] mk_plugin_event_check_return(): Hook 'close' returned -300\n~ 79.559292 [core|mk_plugin.c:985] mk_plugin_event_check_return(): ret = MK_PLUGIN_RET_EVENT_NEXT\n~ 79.559301 [core|mk_epoll.c:359] mk_epoll_del(): [FD 27] Epoll, remove from QUEUE_FD=9\n~ 79.559309 [core|mk_scheduler.c:486] mk_sched_remove_client(): [FD 27] Scheduler remove\n \nthere is nothing pending, looks like the server serve everything but weighttp is still waiting for something more, the same behavior can be seen with apache-benchmark tool (ab). \n\n\n", 
    "reporter": "edsiper", 
    "cc": "", 
    "resolution": "", 
    "_ts": "1388444471918654", 
    "component": "FastCGI", 
    "summary": "FastCGI/PHP strange behavior on high load", 
    "priority": "critical", 
    "keywords": "", 
    "version": "", 
    "time": "2013-12-30T23:01:11", 
    "milestone": "Future Release", 
    "owner": "", 
    "type": "defect"
}

[edsiper]

And if you revert the Epollrdhup commit?
On Mar 19, 2014 1:36 AM, "tssavita" notifications@github.com wrote:

Is the error here that weighttp does not quit and still waits for some
more information ? If that's the case, then I couldn't reproduce the error.
:( When I tried running the server with fastcgi plugin enabled, running the
tool weighttp on another terminal, for the resource test.php, I got the
following output.

----------OUTPUT-----------------
savita@Amrita:~/monkey$ weighttp -n 500 -c 8 -k
http://localhost:2001/test.php
weighttp - a lightweight and simple webserver benchmarking tool

starting benchmark...
spawning thread #1 #1: 8
concurrent requests, 500 total requests
progress: 10% done
progress: 20% done
progress: 30% done
progress: 40% done
progress: 50% done
progress: 60% done
progress: 70% done
progress: 80% done
progress: 90% done
progress: 100% done

finished in 1 sec, 77 millisec and 145 microsec, 464 req/s, 165 kbyte/s
requests: 500 total, 500 started, 500 done, 500 succeeded, 0 failed, 0
errored
status codes: 500 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 183008 bytes total, 113508 bytes http, 69500 bytes data
---------------OUTPUT------------------

Am I in the right direction or am I completely off ?
Please note that I did clone a fresh copy of the repo from github.

Reply to this email directly or view it on GitHubhttps://github.com//issues/97#issuecomment-38024458
.

[tssavita]

I could reproduce the error even after I cloned a new copy of the source code. The following are what I did to reproduce the error:

-- Configured the server ./configure --trace
-- Compile - make
-- From conf/plugins.load, uncomment the line # Load ../monkey-fastcgi.so
-- To /plugins/fastcgi/conf/fastcgi.conf, add the following lines:

---

[FASTCGI_SERVER]
ServerName php5-fpm
ServerPath /var/run/php5-fpm.sock
Maxconnections 5

[FASTCGI_LOCATION]
ServerNames php5-fpm
Match /*.php

---

-- In file /etc/php5/fpm/pool.d/www.conf, change listen = /var/run/php5-fpm.sock
-- Start php5-fpm server by running = sudo /etc/init.d/php5-fpm restart.
-- Run the server: bin/monkey
-- Opened another terminal to send requests concurrently : weighttp -n 500 -c 8 -k http://localhost:2001/test.php
The weighttp got hanged.

[joshin42]

I'm still seeing this with current (1.5.5) on Gentoo (sane flags).

Monkeyd stops talking to php-fpm much like described here: #86. Obviously that bug was fixed, but something is still causing fastcgi to fail.

I've turned keepalive off & on, enabled and disabled jemalloc, and changed maxconnections. The server gets 1 connection every 20 seconds and after 2-5 minutes, stops talking to php-fpm through fastcgi. Static linked pages work fine. Apache using the same php-fpm pool works fine.

Thanks!

[edsiper]

I have re-written the FastCGI plugin in our GIT master and I cannot reproduce the issue. Would you please test on your side ?

note: weighttp is not suitable for testing as it have a bug when reading chunks of data with chunked transfer encoding.

[edsiper]

After new FastCGI implementation I cannot reproduce the problem.