Nginx – MySQL Execution Time Spikes

MySQLnginxPHPphp-fpm

I am having issues with MySQL all of the sudden today.

Details:

  • OS: CentOS release 5.7
  • Server type: Parallels virtuozzo container running on mediatemple DV 4.0 package
  • Average total memory usage: <500mb
  • Total memory usage allowed: 1gb (part of shared pool for emergency only, users are only guaranteed 500mb)
  • Processor: >1ghz
  • Main database sizes with most usage: 275mb & 107mb
  • server stack: nginx 1.0.10, mysql 5.1.54, php 5.3.8 with php-fpm
  • innodb_buffer_pool_size=100M
  • php-fpm max children: 5
  • Webapps: custom php-based sites, magento & drupal
  • slow query timeout is set to 1 second

Steps I completed towards diagnosis:

  1. Cannot restart container yet – I will try later tonight when our domestic traffic has dropped
  2. Enabled mysql and php-fpm slowlog.
  3. Found functions that did DB queries in php-fpm slowlog were taking over 1s to complete at times
  4. Found some simple queries in mysql slowlog taking well over 1s to complete that should take less than 1s.
  5. Most interesting – execution time seems to spike at times. A query will take .2s a couple times, then one time it will take 8s to run the same query. These results were verified by running raw SQL queries through mysql command line.
  6. Top does not reveal anything too interesting
  7. Only resource related thing i can see is load averages much higher than normal
  8. Up until today, mysql has been fine, there have been no major changes to the db since yesterday.
  9. Sometimes things are so bad, I am seeing bad gateway errors after 60s of execution time.
  10. Innodb is doing on average 300-1400 reads/sec.
  11. Mysql is doing 3-10 queries/sec
  12. slow query count in 2 hours uptime is 171 (with slow timeout at 1 second)
  13. Tried restarting mysql, nginx, php-fpm multiple times

For example:

UPDATE  `catalogsearch_query` SET `query_text` = 'EW 90', `num_results` = '7532', `popularity` = '99180', `redirect` = NULL, `synonym_for` = NULL, `store_id` = '1', `display_in_terms` = '1', `is_active` = '1', `is_processed` = '1', `updated_at` =  '2012-05-08 21:38:31' WHERE (query_id='31');

This query took 17sec to complete one time, rest of the time around .079 sec. But varies, sometimes 1sec, sometimes .004 sec. This is running the same query, over and over with a couple seconds time in between each.

Most tables are innodb, and sometimes I noticed the lock time taking 90% of the query execution time, but most of the time lock time is insignificant.

Any idea what's going on here?

Best Answer

Sounds almost definitely like a peripheral issue influencing what is going on and fairly typical of running Magento in a constrained and contended environment like a VPS.

If your configuration was previously working well and you haven't changed any code or installed any extensions - then it will be an external influence, most likely an increase in traffic - but with a VPS, it is more than likely increased I/O activity.

It sounds exactly like I/O wait - simply installing a graphing tool like Munin would conclusively prove this (showing a correlating in MySQL slow queries with I/O activity/wait).

I'll refer to a few other posts on the same vain - as running Magento in a VPS always yields similar behaviour.

  1. https://serverfault.com/a/368649/113375
  2. https://serverfault.com/a/367861/113375
  3. https://stackoverflow.com/a/8216096
Related Topic