I run several PHP websites in Jooma and WordPress on Ubuntu VPS using Nginx as the web server with PHP-FPM for processing PHP. In most cases all the sites work fast enough, but sometimes (probably once a couple days) I got a message from Yandex (Russian search engine like Google) telling that one of my websites did not respond within 5 seconds. I set up Nginx slowlog and detected that sometimes HTTP requests are processed for more than 5 seconds:
[30-Aug-2013 06:00:11] [pool beauty] pid 10150 script_filename = /home/beauty/www/index.php [0x0000000001fd3840] preg_replace() /home/beauty/www/libraries/joomla/filter/filteroutput.php:91 [0x0000000001fd3380] stringURLSafe() /home/beauty/www/components/com_virtuemart/router.php:304 [0x0000000001fd24d8] vmsef_safe_url() /home/beauty/www/components/com_virtuemart/router.php:171 [0x0000000001fd16e0] get_all_alias() /home/beauty/www/components/com_virtuemart/router.php:61 [0x0000000001fd06d0] virtuemartBuildRoute() /home/beauty/www/includes/router.php:311 [0x0000000001fd03b0] _buildSefRoute() /home/beauty/www/libraries/joomla/application/router.php:167 [0x0000000001fcfd40] build() /home/beauty/www/includes/router.php:82 [0x0000000001fcf588] build() /home/beauty/www/libraries/joomla/methods.php:54 [0x0000000001fcd7c0] _() /home/beauty/www/administrator/components/com_virtuemart/classes/ps_session.php:603 [0x0000000001fcc980] url() /home/beauty/www/administrator/components/com_virtuemart/classes/ps_product_category.php:735 [0x0000000001fc91e8] get_category_tree() /home/beauty/www/modules/mod_virtuemart/mod_virtuemart.php:71 [0x0000000001fc7710] +++ dump failed [30-Aug-2013 08:09:06] [pool beauty] pid 11364 script_filename = /home/beauty/www/index.php [0x0000000001f28098] get_all_alias() /home/beauty/www/components/com_virtuemart/router.php:174 [0x0000000001f272a0] get_all_alias() /home/beauty/www/components/com_virtuemart/router.php:61 [0x0000000001f26290] virtuemartBuildRoute() /home/beauty/www/includes/router.php:311 [0x0000000001f25f70] _buildSefRoute() /home/beauty/www/libraries/joomla/application/router.php:167 [0x0000000001f25900] build() /home/beauty/www/includes/router.php:82 [0x0000000001f25148] build() /home/beauty/www/libraries/joomla/methods.php:54 [0x0000000001f23380] _() /home/beauty/www/administrator/components/com_virtuemart/classes/ps_session.php:603 [0x0000000001f22540] url() /home/beauty/www/administrator/components/com_virtuemart/classes/ps_product_category.php:735 [0x0000000001f1eda8] get_category_tree() /home/beauty/www/modules/mod_virtuemart/mod_virtuemart.php:71 [0x0000000001f1d2d0] +++ dump failed [30-Aug-2013 08:48:43] [pool beauty] pid 11485 script_filename = /home/beauty/www/index.php [0x0000000001f2dbf0] htmlentities() /home/beauty/www/libraries/joomla/language/language.php:225 [0x0000000001f2d8e8] transliterate() /home/beauty/www/libraries/joomla/filter/filteroutput.php:88 [0x0000000001f2d428] stringURLSafe() /home/beauty/www/components/com_virtuemart/router.php:304 [0x0000000001f2c580] vmsef_safe_url() /home/beauty/www/components/com_virtuemart/router.php:171 [0x0000000001f2b788] get_all_alias() /home/beauty/www/components/com_virtuemart/router.php:61 [0x0000000001f2a778] virtuemartBuildRoute() /home/beauty/www/includes/router.php:311 [0x0000000001f2a458] _buildSefRoute() /home/beauty/www/libraries/joomla/application/router.php:167 [0x0000000001f29de8] build() /home/beauty/www/includes/router.php:82 [0x0000000001f29630] build() /home/beauty/www/libraries/joomla/methods.php:54 [0x0000000001f27868] _() /home/beauty/www/administrator/components/com_virtuemart/classes/ps_session.php:603 [0x0000000001f25bc8] url() /home/beauty/www/administrator/components/com_xmap/extensions/com_virtuemart.php:222 [0x0000000001f23f10] getCategoryTree() /home/beauty/www/administrator/components/com_xmap/extensions/com_virtuemart.php:178 [0x0000000001f22c80] getCategoryTree() /home/beauty/www/administrator/components/com_xmap/extensions/com_virtuemart.php:123 [0x00007fffad24f4d0] getTree() unknown:0 [0x0000000001f22838] call_user_func_array() /home/beauty/www/administrator/components/com_xmap/classes/XmapPlugins.php:48 [0x0000000001f203e0] printTree() /home/beauty/www/components/com_xmap/xmap.php:455 [0x0000000001f1fa28] printMenuTree() /home/beauty/www/components/com_xmap/xmap.php:320 [0x0000000001f1f2a0] generateSitemap() /home/beauty/www/components/com_xmap/xmap.php:225 [0x0000000001f1c7d0] xmapCallShowSitemap() /home/beauty/www/components/com_xmap/xmap.php:175 [0x0000000001f1b0a8] +++ dump failed
To determine the most probable cause I written a bash script for CPU usage monitoring and it shown me some interesting statistics. As seen from slowlog provided above and the table below the last stack trace was printed at 08:48:43 during sitemap generation that taken about 8 seconds and utilized 100% of 1 CPU core or roughly 12.5% of total 8-core CPU, so we have the situation when PHP script does not have enough CPU power to handle HTTP request within 5 seconds (see cpu_us column and top for more information):
Now let’s take a look at two previous stack traces printed at 06:00:11 and 08:09:06. They utilized 15%-50% of 1 CPU core, and steal time (cpu_st column rounded with blue rectangle) indicates that hypervisor or noisy neighbors are doing something:
If the steal time is shown correctly then the most interesting question is why PHP scripts are unable to use 100% of 1 CPU core as in the case with sitemap generation, but uses only 15%-50%? Another example:
2013-08-30 Steal Time daily maximum was 75.2% and I was constantly getting messages in my php5-fpm.log:
[30-Aug-2013 18:40:08] WARNING: [pool beauty] child 15539, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (5.350266 sec), logging [30-Aug-2013 18:40:15] WARNING: [pool beauty] child 15533, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (5.352170 sec), logging [30-Aug-2013 18:40:17] WARNING: [pool beauty] child 15568, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (5.307516 sec), logging [30-Aug-2013 18:50:07] WARNING: [pool beauty] child 15623, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (5.149803 sec), logging [30-Aug-2013 18:50:07] WARNING: [pool beauty] child 15621, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (6.611944 sec), logging [30-Aug-2013 18:50:07] WARNING: [pool beauty] child 15573, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (6.563567 sec), logging [30-Aug-2013 18:50:09] WARNING: [pool beauty] child 15625, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (5.553833 sec), logging [30-Aug-2013 18:50:09] WARNING: [pool beauty] child 15624, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (6.555829 sec), logging [30-Aug-2013 18:50:10] WARNING: [pool beauty] child 15626, script '/home/beauty/www/index.php' (request: "GET /index.php") executing too slow (6.219799 sec), logging
the last message on this host was 31.08.2013 at 08:25:13.
Migration to a new host
31.08.2013 at 09:00 (05:00 UTC) I migrated my Ubuntu VPS to new physical host and and I did not get any slowlog messages till 22:00 (18:00 UTC) except sitemap generation that always takes more than 5 seconds. The maximum steal time was 55%, but it did not produce any slowlog messages:
