4

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.

  1. 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.
  2. 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

http://pastebin.com/njmmm2CD

12
  • 1
    Do you use APC (pecl.php.net/package/APC) ? Feb 25, 2013 at 15:25
  • Yep we are using APC.
    – Toktik
    Feb 25, 2013 at 15:26
  • We are using APC opcode caching, as well we store/cache some applciation configurations and critical data needed in each request.
    – Toktik
    Feb 25, 2013 at 15:28
  • 2
    Turn on coredumps and analyze segfault dump with gdb - for the start simple bt is enough Feb 25, 2013 at 15:29
  • 1
    First thing I would do is to get rid of APC and replace it with something more stable, like eAccelerator or XCache. APC and crashing with signal 11 are pretty much synonymous. Feb 25, 2013 at 20:57

1 Answer 1

3
+25

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

  • Why is the add failing? Have you some form of update overload causing queue overflow / timeout.
  • Consider just swallowing this and loosing this one session;

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .