更新 2017-11-26
问题似乎与 InnoDB 有关。CI 以及 Wordpress 安装都使用 InnoDB 引擎,而其余部分则使用 MyISAM。在我将所有 MODx 数据库转换为 InnoDB 后,它们遇到了同样的问题……偶尔查询速度非常慢,导致加载时间超过 10 秒。这是我的一个 MODx 站点的监控工具的屏幕截图(您可以看到我昨天从 MyISAM 切换到了 InnoDB,加载时间激增):
这是我的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
数据库统计信息(将 MODx 从 MyISAM 转换为 InnoDB 之后):
- MyISAM 表中的数据:589K(表:16)
- InnoDB 表中的数据:131M(表:1089)
问题
我正在运行一台 CentOS 7 机器,其中装有 Nginx 1.10.2 + PHP 7.1.10 (php-fpm) + MariaDB 10.1.28。使用这台机器,我正在运行以下应用程序:
- 4x Laravel 5.x
- 10x MODx Revo 2.5.8
- 1x Wordpress 4.8.3
- 2x CI 3.1.6
虽然我的 Laravel 和 MODx Revo 应用程序运行速度超快且没有任何问题,但我的状态监视器、慢速日志(PHP-FPM 和 MariaDB Slowlog)和手动测试验证了,从对我的 Wordpress 和 CI 应用程序的大约 10 个请求中,有 3 个请求非常慢(最慢约 5-7 秒),而其他 7 个请求都按预期快速运行。
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';
我还尝试将 CI 中的数据库驱动程序从 PDO 切换到 Mysqli...这并没有改变任何东西。此外,我在 Phpmyadmin 中运行了所有这些慢查询,它们的执行速度非常快...所以最后在 CI 中,我将会话从 DB 切换到 Session_files_driver,导致打印慢日志:
[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
慢速查询的分析
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)