We are experiencing CPU shortage at high-load. It only happens at some point when online users are around 1300-1400 (according google analytics). We are receiving Empty Response in browser.
It seems strange to me that shortage happens unexpectedly. I mean – there is above 50% idle CPU and suddenly it drops to 0% for several seconds, and then jumps back.
Here is the "iostat 1" output for that moment. Look at last column. 70% is the latest normal behavior.
http://pastebin.com/sMjQ0AaJ
All PHP-FPM processes in queue are dying, leaving these logs in /var/log/messages
Feb 25 20:20:01 <kern.info> dasaran kernel: pid 36267 (php-fpm), uid 80: exited on signal 11
Feb 25 20:20:01 <kern.info> dasaran kernel: pid 36265 (php-fpm), uid 80: exited on signal 11
Feb 25 20:20:01 <kern.info> dasaran kernel: pid 36263 (php-fpm), uid 80: exited on signal 11
Feb 25 20:20:01 <kern.info> dasaran kernel: pid 36262 (php-fpm), uid 80: exited on signal 11
Nginx error log
2013/02/25 20:22:14 [error] 34877#0: accept() failed (53: Software caused connection abort)
2013/02/25 20:22:14 [error] 34877#0: accept() failed (53: Software caused connection abort)
2013/02/25 20:22:14 [error] 34877#0: accept() failed (53: Software caused connection abort)
2013/02/25 20:22:14 [error] 34877#0: accept() failed (53: Software caused connection abort)
2013/02/25 20:22:14 [error] 34874#0: accept() failed (53: Software caused connection abort)
I dont understand this behaviour for two reasons.
- If load is causing the CPU shortage, should not the CPU idle drop linearly, not suddenly? But another fact is that this happening at load.
- Why the 0% idle lasts several seconds?
We tried optimizing the scripts, server and database (separate server). It only gave minor increase of peak users.
Server configuration:
FreeBSD 8.3
Intel® Xeon® E3-1245 Quadcore
32 GB ECC RAM
What can cause problems like this?
What strategies should I practice to find the bottleneck?
UPDATE
Here is the gdb output for bt and dump_bt.
(gdb) dump_bt executor_globals.current_execute_data
[0x801827a58] getSaveHandler() /www/svn/zend-libs/Toktik/Session/Set.php:42
[0x8018278d0] Toktik_Session_Set::getSaveHandler() /www/svn/zend-libs/Toktik/Session/Set.php:59
[0x801827630] Toktik_Session_Set->add("6j6omknh8tbr28358gadtp40s7") /www/svn/zend-libs/Toktik/Session/SaveHandler/Phpredis.php:146
[0x7fffffffc350] Toktik_Session_SaveHandler_Phpredis->write("6j6omknh8tbr28358gadtp40s7", "Zend_Auth|a:1:{s:7:"storage";s:7:"3963623";}")
(gdb) bt
#0 0x0000000000695cfe in zend_fetch_var_address_helper_SPEC_CONST_VAR (type=0, execute_data=0x801827a58)
at zend_vm_execute.h:4836
#1 0x00000000006961da in ZEND_FETCH_R_SPEC_CONST_VAR_HANDLER (execute_data=0x801827a58)
at zend_vm_execute.h:4863
#2 0x0000000000680a01 in execute (op_array=0x80dc8e2c8) at zend_vm_execute.h:410
#3 0x000000000063101d in zend_call_function (fci=0x7fffffffc640, fci_cache=0x7fffffffc320)
at /usr/ports/lang/php5/work/php-5.4.10/Zend/zend_execute_API.c:958
#4 0x000000000062fe8a in call_user_function_ex (function_table=0x80185e060, object_pp=0x0,
function_name=0x80dc99b78, retval_ptr_ptr=0x7fffffffc6e8, param_count=2, params=0x80dadcab0,
no_separation=1, symbol_table=0x0) at /usr/ports/lang/php5/work/php-5.4.10/Zend/zend_execute_API.c:750
#5 0x000000000062fcbd in call_user_function (function_table=0x80185e060, object_pp=0x0,
function_name=0x80dc99b78, retval_ptr=0x80dae2670, param_count=2, params=0x7fffffffc7a0)
at /usr/ports/lang/php5/work/php-5.4.10/Zend/zend_execute_API.c:723
#6 0x0000000803cc924f in ps_call_handler () from /usr/local/lib/php/20100525-debug/session.so
#7 0x0000000803cc9924 in ps_write_user () from /usr/local/lib/php/20100525-debug/session.so
#8 0x0000000803cbf4a8 in php_session_save_current_state () from /usr/local/lib/php/20100525-debug/session.so
#9 0x0000000803cc3d06 in php_session_flush () from /usr/local/lib/php/20100525-debug/session.so
#10 0x0000000803cc5cd9 in zm_deactivate_session () from /usr/local/lib/php/20100525-debug/session.so
#11 0x000000000064f121 in zend_deactivate_modules () at /usr/ports/lang/php5/work/php-5.4.10/Zend/zend_API.c:2335
#12 0x00000000005b8aea in php_request_shutdown (dummy=0x0)
at /usr/ports/lang/php5/work/php-5.4.10/main/main.c:1759
#13 0x000000000079ec06 in main (argc=1, argv=0x7fffffffed58)
at /usr/ports/lang/php5/work/php-5.4.10/sapi/fpm/fpm/fpm_main.c:1948
Here is the classes responsible for session management using phpredis (dump_bt points to these)
http://pastebin.com/kaRNXGCa
Best Answer
Sorry not a proper answer, but a bit too long for a comment.
What the stack is saying is that the execution engine barfed on a user callback during session shutdown. This was when your session handler Toktik_Session_SaveHandler_Phpredis::write threw an exception at line 146. I don't know why the add failed, but throwing exceptions during image rundown is a bad idea. So