Occasional slow database queries caused by InnoDB

Question

Update 2017-11-26

The problem seems to be related to InnoDB. The CI as well as the Wordpress installations are using InnoDB Engines while the rest is working with MyISAM. After I converted all MODx Databases to InnoDB they are having the same issues...Occasional very slow queries causing loading times of > 10 seconds. Here's a screenshot of my monitoring tool from one of my MODx sites (you can see that I switched from MyISAM to InnoDB yesterday and the loading time exploded):

Here is my my.cnf:

skip_name_resolve               = 1
thread_cache_size               = 4
performance_schema
query_cache_type                = 0
query_cache_limit               = 0
query_cache_size                = 0
join_buffer_size                = 4M
tmp_table_size                  = 250M
max_heap_table_size             = 250M


innodb_buffer_pool_instances    = 1
innodb_log_file_size            = 16M
innodb_buffer_pool_size         = 185M
innodb_io_capacity              = 2000
innodb_read_io_threads          = 64
innodb_thread_concurrency       = 0
innodb_write_io_threads         = 64
innodb_flush_log_at_trx_commit  = 0
innodb_log_file_size            = 23M

Database Statistics (after converted MODx from MyISAM to InnoDB):

Data in MyISAM tables: 589K (Tables: 16)
Data in InnoDB tables: 131M (Tables: 1089)

Problem

I am running a CentOS 7 machine with Nginx 1.10.2 + PHP 7.1.10 (php-fpm) + MariaDB 10.1.28. Using this machine I am serving the following applications:

4x Laravel 5.x
10x MODx Revo 2.5.8
1x Wordpress 4.8.3
2x CI 3.1.6

While my Laravel and MODx Revo applications are running super fast without any issues, my status monitors, slow logs (PHP-FPM and MariaDB Slowlog) and manual testing verify that from approx. 10 requests to my Wordpress and CI applications 3 reqs. are very slow (slowest around 5-7 seconds) while the other 7 reqs. are quick as expected.

Wordpress

www-slow.log (PHP-FPM)

[13-Nov-2017 09:44:09]  [pool www] pid 24000
script_filename = /usr/share/nginx/www/wordpress/index.php
[0x00007ff6f7412aa0] mysqli_query() /usr/share/nginx/www/wordpress/wp-includes/wp-db.php:1942
[0x00007ff6f7412a20] _do_query() /usr/share/nginx/www/wordpress/wp-includes/wp-db.php:1830
[0x00007ff6f7412940] query() /usr/share/nginx/www/wordpress/wp-includes/wp-db.php:2185
[0x00007ff6f74127f0] update() /usr/share/nginx/www/wordpress/wp-includes/option.php:342
[0x00007ff6f74126d0] update_option() /usr/share/nginx/www/wordpress/wp-includes/class-wp-rewrite.php:1817
[0x00007ff6f7412630] flush_rules() /usr/share/nginx/www/wordpress/wp-includes/class-wp-hook.php:298
[0x00007ff6f7412550] apply_filters() /usr/share/nginx/www/wordpress/wp-includes/class-wp-hook.php:323
[0x00007ff6f74124e0] do_action() /usr/share/nginx/www/wordpress/wp-includes/plugin.php:453
[0x00007ff6f74123e0] do_action() /usr/share/nginx/www/wordpress/wp-settings.php:469
[0x00007ff6f7412230] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/wordpress/wp-config.php:117
[0x00007ff6f74121b0] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/wordpress/wp-load.php:37
[0x00007ff6f7412110] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/wordpress/wp-blog-header.php:13
[0x00007ff6f7412080] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/wordpress/index.php:17

slow.log (MariaDB)

# User@Host: wordpress[wordpress] @ localhost []
# Thread_id: 6810  Schema: wordpress  QC_hit: No
# Query_time: 19.189590  Lock_time: 0.000046  Rows_sent: 0  Rows_examined: 1
# Rows_affected: 1
#
# explain: id   select_type table   type    possible_keys   key key_len ref rows    r_rows  filtered    r_filtered  Extra
# explain: 1    SIMPLE  wp_options  range   option_name option_name 766 NULL    1   1.00    100.00  100.00  Using where
#
SET timestamp=1510527877;
UPDATE `wp_options` SET `option_value` = '' WHERE `option_name` = 'rewrite_rules';

CI

www-slow.log (PHP-FPM)

[12-Nov-2017 23:08:02]  [pool www] pid 23991
    script_filename = /usr/share/nginx/www/ci/index.php
    [0x00007ff6f74133c0] query() /usr/share/nginx/www/ci/system/database/drivers/pdo/pdo_driver.php:184
    [0x00007ff6f7413350] _execute() /usr/share/nginx/www/ci/system/database/DB_driver.php:791
    [0x00007ff6f74132e0] simple_query() /usr/share/nginx/www/ci/system/database/DB_driver.php:654
    [0x00007ff6f74131b0] query() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_database_driver.php:358
    [0x00007ff6f7413110] _get_lock() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_database_driver.php:151
    [0x00007ff6f7413080] read() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
    [0x00007ff6f7413030] session_start() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
    [0x00007ff6f7412f60] __construct() /usr/share/nginx/www/ci/system/core/Loader.php:1279
    [0x00007ff6f7412e40] _ci_init_library() /usr/share/nginx/www/ci/system/core/Loader.php:1172
    [0x00007ff6f7412d20] _ci_load_stock_library() /usr/share/nginx/www/ci/system/core/Loader.php:1037
    [0x00007ff6f7412c10] _ci_load_library() /usr/share/nginx/www/ci/system/core/Loader.php:1083
    [0x00007ff6f7412b00] _ci_load_library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:173
    [0x00007ff6f7412a00] library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:192
    [0x00007ff6f7412950] libraries() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:153
    [0x00007ff6f7412850] library() /usr/share/nginx/www/ci/system/core/Loader.php:1353
    [0x00007ff6f7412790] _ci_autoloader() /usr/share/nginx/www/ci/system/core/Loader.php:157
    [0x00007ff6f7412740] initialize() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:65
    [0x00007ff6f7412690] initialize() /usr/share/nginx/www/ci/system/core/Controller.php:79
    [0x00007ff6f74125f0] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:55
    [0x00007ff6f7412560] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:60

slow.log (MariaDB)

# Time: 171112 23:08:05
# User@Host: ci[ci] @ localhost []
# Thread_id: 6445  Schema: pm  QC_hit: No
# Query_time: 16.833340  Lock_time: 0.000049  Rows_sent: 0  Rows_examined: 168
# Rows_affected: 1
#
# explain: id   select_type table   type    possible_keys   key key_len ref rows    r_rows  filtered    r_filtered  Extra
# explain: 1    SIMPLE  ci_un_sessions  ALL NULL    NULL    NULL    NULL    168 168.00  100.00  0.60    Using where
#
use pm;
SET timestamp=1510524485;
UPDATE `ci_un_sessions` SET `timestamp` = 1510524468, `data` = '__ci_last_regenerate|i:1510524343;requested_page|s:41:\"http://example.com/projects/view/19\";user_id|s:1:\"1\";username|s:9:\"admin\";role_id|s:1:\"1\";status|s:1:\"1\";previous_page|s:41:\"http://example.com/projects/view/19\";'
WHERE `id` = '0a75c6tl27pngqnfrh261okdvuotth50';

I also tried to switch the database driver in CI from PDO to Mysqli...this didn't change anything. Also I ran all those slow queries in Phpmyadmin, and they perform super fast...so finally in CI I switched session from DB to Session_files_driver causing the slowlog to print:

[12-Nov-2017 23:27:00]  [pool www] pid 23991
script_filename = /usr/share/nginx/www/ci/index.php
[0x00007ff6f7413140] flock() /usr/share/nginx/www/ci/system/libraries/Session/drivers/Session_files_driver.php:178
[0x00007ff6f7413080] read() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
[0x00007ff6f7413030] session_start() /usr/share/nginx/www/ci/system/libraries/Session/Session.php:143
[0x00007ff6f7412f60] __construct() /usr/share/nginx/www/ci/system/core/Loader.php:1279
[0x00007ff6f7412e40] _ci_init_library() /usr/share/nginx/www/ci/system/core/Loader.php:1172
[0x00007ff6f7412d20] _ci_load_stock_library() /usr/share/nginx/www/ci/system/core/Loader.php:1037
[0x00007ff6f7412c10] _ci_load_library() /usr/share/nginx/www/ci/system/core/Loader.php:1083
[0x00007ff6f7412b00] _ci_load_library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:173
[0x00007ff6f7412a00] library() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:192
[0x00007ff6f7412950] libraries() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:153
[0x00007ff6f7412850] library() /usr/share/nginx/www/ci/system/core/Loader.php:1353
[0x00007ff6f7412790] _ci_autoloader() /usr/share/nginx/www/ci/system/core/Loader.php:157
[0x00007ff6f7412740] initialize() /usr/share/nginx/www/ci/application/third_party/MX/Loader.php:65
[0x00007ff6f7412690] initialize() /usr/share/nginx/www/ci/system/core/Controller.php:79
[0x00007ff6f74125f0] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:55
[0x00007ff6f7412560] __construct() /usr/share/nginx/www/ci/application/third_party/MX/Base.php:60
[0x00007ff6f7412500] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Controller.php:4
[0x00007ff6f74124a0] [INCLUDE_OR_EVAL]() /usr/share/nginx/www/ci/application/third_party/MX/Modules.php:123
[0x00007ff6f7412400] autoload() unknown:0
[0x00007ff6f74123a0] spl_autoload_call() unknown:0

Profiling of a slow query

MariaDB [user]> UPDATE `fx_un_sessions` SET `timestamp` = 1511872955 WHERE `id` = 'hrpsbbvr785cndmmo9n1iqnrek7teqi3';
Query OK, 0 rows affected (8.07 sec)
Rows matched: 1  Changed: 0  Warnings: 0

+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000097 |
| checking permissions | 0.000015 |
| Opening tables       | 0.000031 |
| After opening tables | 0.000013 |
| System lock          | 0.000012 |
| Table lock           | 0.000012 |
| init                 | 0.000065 |
| updating             | 0.000088 |
| end                  | 0.000016 |
| query end            | 8.077103 |
| closing tables       | 0.000059 |
| Unlocking tables     | 0.000034 |
| freeing items        | 0.000019 |
| updating status      | 0.000032 |
| logging slow query   | 0.000136 |
| cleaning up          | 0.000035 |
+----------------------+----------+
16 rows in set (0.00 sec)

Looks like there is issue with MySQL. It's slow. Could you show MySQL configuration? — Alexander Tolkachev, Nov 15 '17 at 11:30
Yes, but I also tried to change session driver of CI to file instead of database and even here I received slow logs in php-fpm. I updated my post to show my server.cnf configuration. The rest is basically default. Do you need more information? — travisbotello, Nov 16 '17 at 16:17
@AlexanderTolkachev You were right, the problem is related to MySQL, not in general but to InnoDB Engine. After I converted my MODx Databases from MyISAM to InnoDB they are having the same issues as CI and Wordpress (which are using InnoDB). Any ideas? — travisbotello, Nov 26 '17 at 11:10

Occasional slow database queries caused by InnoDB

0 Answers0