MySQL 服务器上的 CPU 系统时间使用率高
一点背景故事，前段时间我们开始在我们的一个 MySQL 数据库上体验高 CPU 系统时间。该数据库的磁盘利用率也很高，因此我们认为这些东西是相互连接的。由于我们已经计划将其迁移到 SSD，我们认为它可以解决这两个问题。
它有帮助……但时间不长。
迁移后的几周 CPU 图是这样的：
但现在我们又回到了这个：
这突然发生，负载或应用程序逻辑没有任何明显变化。
数据库统计：
- MySQL 版本 - 5.7.20
- 操作系统 - Debian
- 数据库大小 - 1.2Tb
- 内存 - 700Gb
- CPU 核心 - 56
- Peek 负载 - 大约 5kq/s 读取，600q/s 写入（尽管选择查询通常非常复杂）
- 线程 - 50 个运行，300 个连接
- 它有大约 300 个表，都是 InnoDB
MySQL配置：
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock
[mysqld_safe]
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
nice = 0
[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /opt/mysql-data
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
explicit_defaults_for_timestamp
sql_mode = STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
log-error = /opt/mysql-log/error.log
# Replication
server-id = 76
gtid-mode = ON
enforce-gtid-consistency = true
relay-log = /opt/mysql-log/mysql-relay-bin
relay-log-index = /opt/mysql-log/mysql-relay-bin.index
replicate-wild-do-table = dbname.%
log-bin = /opt/mysql-log/mysql-bin.log
expire_logs_days = 7
max_binlog_size = 1024M
binlog-format = ROW
log-bin-trust-function-creators = 1
log_slave_updates = 1
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
# * IMPORTANT: Additional settings that can override those from this file!
# The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/
# Here goes
skip_name_resolve = 1
general_log = 0
slow_query_log = 1
slow_query_log_file = /opt/mysql-log/slow.log
long_query_time = 3
max_allowed_packet = 16M
max_connections = 700
max_execution_time = 200000
open_files_limit = 32000
table_open_cache = 8000
thread_cache_size = 128
innodb_buffer_pool_size = 550G
innodb_buffer_pool_instances = 28
innodb_log_file_size = 15G
innodb_log_files_in_group = 2
innodb_flush_method = O_DIRECT
max_heap_table_size = 16M
tmp_table_size = 128M
join_buffer_size = 1M
sort_buffer_size = 2M
innodb_lru_scan_depth = 256
query_cache_type = 0
query_cache_size = 0
innodb_temp_data_file_path = ibtmp1:12M:autoextend:max:30G
其他观察
PERF峰值加载期间的MySQL过程的：
68,31% 68,31% mysqld [kernel.kallsyms] [k] _raw_spin_lock
- _raw_spin_lock
+ 51,63% 0x7fd118e9dbd9
+ 48,37% 0x7fd118e9dbab
+ 37,36% 0,02% mysqld libc-2.19.so [.] 0x00000000000f4bd9
+ 33,83% 0,01% mysqld libc-2.19.so [.] 0x00000000000f4bab
+ 26,92% 0,00% mysqld libpthread-2.19.so [.] start_thread
+ 26,82% 0,00% mysqld mysqld [.] pfs_spawn_thread
+ 26,82% 0,00% mysqld mysqld [.] handle_connection
+ 26,81% 0,01% mysqld mysqld [.] do_command(THD*)
+ 26,65% 0,02% mysqld mysqld [.] dispatch_command(THD*, COM_DATA const*, enum_server_command)
+ 26,29% 0,01% mysqld mysqld [.] mysql_parse(THD*, Parser_state*)
+ 24,85% 0,01% mysqld mysqld [.] mysql_execute_command(THD*, bool)
+ 23,61% 0,00% mysqld mysqld [.] handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)
+ 23,54% 0,00% mysqld mysqld [.] 0x0000000000374103
+ 19,78% 0,00% mysqld mysqld [.] JOIN::exec()
+ 19,13% 0,15% mysqld mysqld [.] sub_select(JOIN*, QEP_TAB*, bool)
+ 13,86% 1,48% mysqld mysqld [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)
+ 8,48% 0,25% mysqld mysqld [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)
+ 7,93% 0,00% mysqld [unknown] [.] 0x00007f40c4d7a6f8
+ 7,57% 0,00% mysqld mysqld [.] 0x0000000000828f74
+ 7,25% 0,11% mysqld mysqld [.] handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int)
它表明 mysql 在spin_locks上花费了大量时间。我希望得到一些关于这些锁来自哪里的线索，遗憾的是，没有运气。
高负载期间的查询配置文件显示了大量的上下文切换。我使用select * from MyTable where pk = 123，MyTable有大约 90M 行。配置文件输出：
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
starting 0,000756 0,028000 0,012000 81 1 0 0 0 0 0 0 0
checking permissions 0,000057 0,004000 0,000000 4 0 0 0 0 0 0 0 0 check_access sql_authorization.cc 810
Opening tables 0,000285 0,008000 0,004000 31 0 0 40 0 0 0 0 0 open_tables sql_base.cc 5650
init 0,000304 0,012000 0,004000 31 1 0 0 0 0 0 0 0 handle_query sql_select.cc 121
System lock 0,000303 0,012000 0,004000 33 0 0 0 0 0 0 0 0 mysql_lock_tables lock.cc 323
optimizing 0,000196 0,008000 0,004000 20 0 0 0 0 0 0 0 0 optimize sql_optimizer.cc 151
statistics 0,000885 0,036000 0,012000 99 6 0 0 0 0 0 0 0 optimize sql_optimizer.cc 367
preparing 0,000794 0,000000 0,096000 76 2 32 8 0 0 0 0 0 optimize sql_optimizer.cc 475
executing 0,000067 0,000000 0,000000 10 1 0 0 0 0 0 0 0 exec sql_executor.cc 119
Sending data 0,000469 0,000000 0,000000 54 1 32 0 0 0 0 0 0 exec sql_executor.cc 195
end 0,000609 0,000000 0,016000 64 4 0 0 0 0 0 0 0 handle_query sql_select.cc 199
query end 0,000063 0,000000 0,000000 3 1 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 4968
closing tables 0,000156 0,000000 0,000000 20 4 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 5020
freeing items 0,000071 0,000000 0,004000 7 1 0 0 0 0 0 0 0 mysql_parse sql_parse.cc 5596
cleaning up 0,000533 0,024000 0,008000 62 0 0 0 0 0 0 0 0 dispatch_command sql_parse.cc 1902
Peter Zaitsev最近发表了一篇关于上下文切换的帖子，他说：
但是，在现实世界中，如果每个查询的上下文切换少于 10 个，我不会担心争用会成为一个大问题。
但它显示了 600 多个开关！
什么会导致这些症状，可以采取什么措施？我将感谢有关此事的任何指示或信息，到目前为止我遇到的一切都相当陈旧和/或不确定。
PS 如果需要，我很乐意提供其他信息。
SHOW GLOBAL STATUS 和 SHOW VARIABLES 的输出
我无法在此处发布，因为内容超出了帖子大小限制。
iostat
avg-cpu: %user %nice %system %iowait %steal %idle
7,35 0,00 5,44 0,20 0,00 87,01
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 8,00 0,00 32,00 32,00 0,00 32,00 0,00
sda 0,04 2,27 0,13 0,96 0,86 46,52 87,05 0,00 2,52 0,41 2,80 0,28 0,03
sdb 0,21 232,57 30,86 482,91 503,42 7769,88 32,21 0,34 0,67 0,83 0,66 0,34 17,50
avg-cpu: %user %nice %system %iowait %steal %idle
9,98 0,00 77,52 0,46 0,00 12,04
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 1,60 0,00 0,60 0,00 8,80 29,33 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 566,40 55,60 981,60 889,60 16173,60 32,90 0,84 0,81 0,76 0,81 0,51 53,28
avg-cpu: %user %nice %system %iowait %steal %idle
11,83 0,00 72,72 0,35 0,00 15,10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 2,60 0,00 0,40 0,00 12,00 60,00 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 565,20 51,60 962,80 825,60 15569,60 32,32 0,85 0,84 0,98 0,83 0,54 54,56
更新 2018-03-15
> show global status like 'uptime%'
Uptime;720899
Uptime_since_flush_status;720899
> show global status like '%rollback'
Com_rollback;351422
Com_xa_rollback;0
Handler_rollback;371088
Handler_savepoint_rollback;0
每次提交刷新的 600q/s 写入可能会达到您当前旋转磁盘的限制。改用 SSD 可以缓解压力。
快速修复（在获得 SSD 之前）可能是更改为以下设置：
innodb_flush_log_at_trx_commit = 2
但请阅读有关进行更改的注意事项。
拥有该设置和SSD 可以让您进一步发展。
另一种可能的解决方法是将一些写入合并为一个COMMIT（不违反逻辑）。
几乎总是，高 CPU 和/或 I/O 是由于索引不佳和/或查询公式不佳造成的。用 开启slowlog long_query_time=1，稍等片刻，然后看看会出现什么。在手的查询，提供SELECT，EXPLAIN SELECT ...和SHOW CREATE TABLE。写入查询同上。从这些中，我们可能可以驯服 CPU 和/或 I/O。即使使用您当前的 设置3，pt-query-digest也可能会发现一些有趣的事情。
请注意，有50 个“正在运行”的线程，有很多争用；这可能会导致您注意到的切换等。我们需要让查询更快地完成。使用 5.7，系统可能会因 100 个正在运行的线程而崩溃。增加到大约 64 之后，上下文切换、互斥锁、锁等会合谋减慢每个线程的速度，导致吞吐量没有提高，而延迟却达到顶峰。
对于分析问题的不同方法，请提供SHOW VARIABLES和SHOW GLOBAL STATUS？更多讨论在这里。
变量和状态分析
（对不起，在解决您的问题时没有任何内容。）
观察：
- 版本：5.7.20-log
- 700 GB 内存
- 正常运行时间 = 36 天 13:21:34
- 您不是在 Windows 上运行。
- 运行 64 位版本
- 您似乎完全（或大部分）在运行 InnoDB。
更重要的问题：
许多临时表，尤其是基于磁盘的，是为复杂查询创建的。让我们希望慢日志能识别出一些可以改进的查询（通过索引/重构等）。其他指标是没有索引的连接和 sort_merge_passes；然而，这些都不是决定性的，我们需要查看查询。
Max_used_connections = 701is >= Max_connections = 700，所以可能有一些连接被拒绝。此外，如果这表明运行的线程数超过 64 个，那么当时系统性能可能会受到影响。考虑通过限制客户端来限制连接数。您使用的是 Apache、Tomcat 还是其他什么？70Threads_running表示，在执行此操作的那一刻SHOW，系统有问题。
增加每个语句的数量COMMIT（在合理的情况下）可能有助于提高性能。
innodb_log_file_size，15GB，比需要的大，但我认为没有必要改变它。
数以千计的表通常不是一个好的设计。
eq_range_index_dive_limit = 200我很担心，但我不知道如何建议。是故意的选择吗？
为什么有这么多 CREATE+DROP PROCEDURE ？
为什么有这么多 SHOW 命令？
细节和其他观察：
( Innodb_buffer_pool_pages_flushed ) = 523,716,598 / 3158494 = 165 /sec -- 写入（刷新） -- 检查 innodb_buffer_pool_size
( table_open_cache ) = 10,000 -- 要缓存的表描述符的数量 -- 通常几百个就可以了。
( (Innodb_buffer_pool_reads + Innodb_buffer_pool_pages_flushed) ) = ((61,040,718 + 523,716,598) ) / 3158494 = 185 /sec -- InnoDB I/O
( Innodb_dblwr_pages_written/Innodb_pages_written ) = 459,782,684/523,717,889 = 87.8% -- 好像这些值应该相等？
( Innodb_os_log_written ) = 1,071,443,919,360 / 3158494 = 339226 /sec-- 这是 InnoDB 繁忙程度的一个指标。-- 非常繁忙的 InnoDB。
( Innodb_log_writes ) = 110,905,716 / 3158494 = 35 /sec
( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 1,071,443,919,360 / (3158494 / 3600) / 2 / 15360M = 0.0379 -- 比率 -- （见分钟）
( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 3,158,494 / 60 * 15360M / 1071443919360 = 791-- InnoDB 日志轮换之间的分钟数从 5.6.8 开始，可以动态更改；一定也要更改my.cnf。--（轮换间隔60分钟的建议有点武断。）调整innodb_log_file_size。（无法在 AWS 中更改。）
( Com_rollback ) = 770,457 / 3158494 = 0.24 /sec-- InnoDB 中的回滚。-- 回滚频率过高可能表明应用逻辑效率低下。
( Innodb_row_lock_waits ) = 632,292 / 3158494 = 0.2 /sec-- 获得行锁延迟的频率。-- 可能是由可以优化的复杂查询引起的。
( Innodb_dblwr_writes ) = 97,725,876 / 3158494 = 31 /sec-- “双写缓冲区”写入磁盘。“双写”是一种可靠性功能。一些较新的版本/配置不需要它们。--（其他问题的症状）
( Innodb_row_lock_current_waits ) = 13-- InnoDB 表上的操作当前正在等待的行锁数。零是很正常的。——有大事发生吗？
( innodb_print_all_deadlocks ) = OFF-- 是否记录所有死锁。-- 如果您受到死锁的困扰，请打开它。注意：如果您有很多死锁，这可能会向磁盘写入大量内容。
( local_infile ) = ON
-- local_infile = ON 是一个潜在的安全问题
( bulk_insert_buffer_size / _ram ) = 8M / 716800M = 0.00%-- 多行插入和加载数据的缓冲区 -- 太大可能会威胁到 RAM 大小。太小可能会阻碍此类操作。
( Questions ) = 9,658,430,713 / 3158494 = 3057 /sec-- 查询（SP 之外） -- "qps" -- > 2000可能会给服务器带来压力
( Queries ) = 9,678,805,194 / 3158494 = 3064 /sec-- 查询（包括内部 SP） -- > 3000可能会给服务器带来压力
( Created_tmp_tables ) = 1,107,271,497 / 3158494 = 350 /sec -- 创建“临时”表作为复杂 SELECT 的一部分的频率。
( Created_tmp_disk_tables ) = 297,023,373 / 3158494 = 94 /sec-- 创建磁盘“临时”表作为复杂 SELECT 的一部分的频率-- 增加 tmp_table_size 和 max_heap_table_size。检查何时使用 MEMORY 而不是 MyISAM 的临时表规则。也许小的架构或查询更改可以避免 MyISAM。更好的索引和查询的重新制定更有可能有所帮助。
( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (693300264 + 214511608 + 37537668 + 0) / 1672382928 = 0.565-- 每个提交的语句数（假设所有 InnoDB） -- 低：可能有助于在事务中将查询组合在一起；高：多头交易紧张各种事情。
( Select_full_join ) = 338,957,314 / 3158494 = 107 /sec -- 不带索引的连接 -- 向 JOIN 中使用的表添加合适的索引。
( Select_full_join / Com_select ) = 338,957,314 / 6763083714 = 5.0% -- 无索引连接的选择百分比 -- 将合适的索引添加到 JOIN 中使用的表。
( Select_scan ) = 124,606,973 / 3158494 = 39 /sec -- 全表扫描 -- 添加索引/优化查询（除非它们是小表）
( Sort_merge_passes ) = 1,136,548 / 3158494 = 0.36 /sec -- 大量排序 -- 增加 sort_buffer_size 和/或优化复杂查询。
( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (693300264 + 37537668 + 198418338 + 0 + 214511608 + 79274476) / 3158494 = 387 /sec -- 写入/秒 -- 50 次写入/秒 + 日志刷新可能会最大化普通驱动器的 I/O 写入容量
( ( Com_stmt_prepare - Com_stmt_close ) / ( Com_stmt_prepare + Com_stmt_close ) ) = ( 39 - 38 ) / ( 39 + 38 ) = 1.3%-- 你要结束你准备好的陈述吗？-- 添加关闭。
( Com_stmt_close / Com_stmt_prepare ) = 38 / 39 = 97.4%-- 准备好的语句应该是 Closed。-- 检查所有Prepared 语句是否都“关闭”。
( innodb_autoinc_lock_mode ) = 1-- Galera: 欲望 2 -- 2 = "交错"; 1 =“连续”是典型的；0 =“传统”。
( Max_used_connections / max_connections ) = 701 / 700 = 100.1% -- 连接的峰值百分比 -- 增加 max_connections 和/或减少 wait_timeout
( Threads_running - 1 ) = 71 - 1 = 70 -- 活动线程（收集数据时的并发性） -- 优化查询和/或模式
异常大：（ 其中大部分源于一个非常繁忙的系统。）
Com_commit = 529 /sec
Com_create_procedure = 0.01 /HR
Com_drop_procedure = 0.01 /HR
Com_delete = 12 /sec
Com_delete_multi = 63 /sec
Com_insert = 219 /sec
Com_kill = 0.69 /HR
Com_reset = 0.0011 /HR
Com_revoke = 0.0023 /HR
Com_select = 2141 /sec
Com_show_binlogs = 12 /HR
Com_show_create_func = 0.011 /HR
Com_show_privileges = 0.0034 /HR
Com_show_profile = 0.027 /HR
Com_show_profiles = 0.028 /HR
Com_show_slave_status = 0.037 /sec
Com_show_storage_engines = 12 /HR
Com_show_warnings = 0.14 /sec
Com_slave_stop = 0.0011 /HR
Com_update_multi = 25 /sec
Created_tmp_files = 0.3 /sec
Handler_commit = 3251 /sec
Handler_external_lock = 18787 /sec
Handler_prepare = 615 /sec
Handler_read_first = 239 /sec
Handler_read_key = 173669 /sec
Handler_read_next = 1291439 /sec
Handler_read_prev = 28535 /sec
Handler_read_rnd = 32789 /sec
（继续）
Innodb_buffer_pool_bytes_dirty = 7.03e+10
Innodb_buffer_pool_pages_data = 3.41e+7
Innodb_buffer_pool_pages_dirty = 4.29e+6
Innodb_buffer_pool_pages_misc = 2.15e+6
Innodb_buffer_pool_pages_total = 3.62e+7
Innodb_data_fsyncs = 132 /sec
Innodb_data_writes = 232 /sec
Innodb_data_written = 5440151 /sec
Innodb_dblwr_pages_written = 145 /sec
Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group = 582.3MB
Innodb_pages_written = 165 /sec
Innodb_row_lock_time = 5.97e+7
Innodb_rows_deleted + Innodb_rows_inserted = 2180 /sec
Innodb_rows_inserted = 2155 /sec
Innodb_rows_read = 1398531 /sec
Max_used_connections = 701
Open_tables = 10,000
Select_full_range_join = 2.57e+7
Select_range = 130 /sec
Sort_range = 30 /sec
Sort_scan = 332 /sec
Table_open_cache_hits = 9354 /sec
Threads_running = 71
eq_range_index_dive_limit = 200
innodb_purge_threads = 4
innodb_thread_sleep_delay = 16,925
我们从来没有弄清楚这个问题的确切原因是什么，但为了提供一些结束，我会告诉我我能做些什么。
我们的团队进行了一些负载测试并得出结论，MySQL分配内存有问题。所以他们尝试使用jemalloc而不是，glibc问题就消失了。我们已经jemalloc在生产中使用了 6 个多月，再也没有看到这个问题。
我并不是说那jemalloc更好，或者每个人都应该将它与MySQL. 但对于我们的具体案例，似乎glibc无法正常工作。
| 归档时间： |
|
| 查看次数： |
10473 次 |
| 最近记录： |