DevOps system cpu time飙高导致MySQL不可用

vllibertad · November 10, 2019 · 3 hits

最近线上应用出现了一个诡异问题,在访问量无明显增长、线上未做任何变更(代码发布和 DB 操作)的情况下,某个业务子系统突然出现大量的业务接口超时,MySQL 性能急剧下降,系统不可用。

故障现场

当时观察到的主要异常现象包括 MySQL 出现大量的慢查询、MySQL 服务器的 system cpu time 飙高、MySQL 的性能急剧下降、业务接口响应时间飙高、业务系统大量出现获取不到 DB connection 的异常日志等现象。当时的主要信息如下。

慢查询

慢查询主要集中在这个 SQL 上。极其简单的一个 SQL 是不是?读取的数量不到 6K

12345678
select     count(*)from    invoice_push_recordwhere    create_time >= '2017-07-01 00:00:00'
   and create_time < '2017-08-01 00:00:00'
 and invoice_type = 'XXX'

从慢查询日志中看出这个 SQL 的执行时间是 10s,但是平时这个 SQL 的执行时间都在 0.01ms 以内

slow query

  • system cpu time 飙高

MySQL 服务器的 sy 平时不到 5%;故障期间飙高到 77%,而 us 和 load 均未出现波动

system cpu time飙高

  • MySQL 的性能急剧下降

QPS

  • 业务接口

业务服务接口的 QPS 在 30 左右未发生明显变化,但是响应时间从 0.01ms 飙高到 10s

业务接口的QPS和响应时间

临时解决方案

为了快速恢复故障,将影响降到最低,我们采取了以下两个措施

  1. 直接 kill 慢查询

    借助 pt-kill 工具直接干掉慢查询(–match-info “SELECT|select” ),但是由于这个 SQL 的 QPS 比较高,即使在不断地 kill SQL,但是还不断地出现,DB 依旧不可用,故障未恢复。悲催了是不是?

  2. 服务降级

    kill SQL 无效,只能下线和这个 SQL 相关的业务服务接口。将相关的业务服务接口下线后,MySQL 服务器的 sy 逐渐恢复,故障恢复。

故障是否由这条 SQL 导致呢?这个 SQL 的嫌疑比较大

故障排查

变更往往是导致故障的主要原因,所以我们先看看故障发生之前,发生过哪些变更。经过确认

线上代码未做过任何变更

MySQL 的日常维护未执行过

业务流量未发生明显变化

该 SQL 在线上已经运行过 1 年多,不是最近新上线的 SQL

网络监控一切正常

因此排除了因变更导致 MySQL 变慢的情况,由于该业务接口下线后,故障逐渐恢复,所以该 SQL 存在最大的嫌疑

  • slow query 分析

该 SQL 和表都非常简单,这个表的数据量是 1W+。平时在线上执行该 SQL 时,执行时间在 0.01ms 以下

12345678
select     count(*)from    invoice_push_recordwhere    create_time >= '2017-07-01 00:00:00'
   and create_time < '2017-08-01 00:00:00'
 and invoice_type = 'XXX'
123456789
CREATE TABLE `invoice_push_record` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT '自增主键',
`order_id` bigint(20) NOT NULL DEFAULT '0' COMMENT '订单ID',
`invoice_type` varchar(64) NOT NULL DEFAULT '' COMMENT 'XXX类型',
`create_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',PRIMARY KEY (`id`),
UNIQUE KEY `uniq_order_id` (`order_id`),
KEY `idx_create_time_invoice_type` (`create_time`,`invoice_type`)) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4 COMMENT='XXX记录表'
  • system cpu time 高

第一次遇到这类问题,于是查找了相关资源,发现在数据库内核月报里面提及到:当 time_zone 设置为 SYSTEM 时,MySQL 访问到的 timestamp 字段都会作时区转换,在进行时区转换时会竞争全局的 mutex,当大量并发访问 timestamp 时,会引起大量竞争 mutex,从而导致 sy 飙高。

该 SQL 正好使用到了 timestamp,并且线上 MySQL 的 time_zone 是SYSTEM,所以很可能是 timestamp 导致的

12345678
mySQL> show variables like '%time_zone%';     +------------------+--------+  | Variable_name    | Value  |  +------------------+--------+  | system_time_zone | CST    |  | time_zone        | SYSTEM |  +------------------+--------+  2 rows in set (0.00 sec)

考虑到 timestamp 在其他的业务场景中也被广泛使用到,但未出现过类似问题,所以当时并不能确定是 timestamp 导致的

初步结论:尚无定论,有可能是 timestamp 的 time_zone 导致,待继续排查

故障重现

为了保证再次出现问题时能及时恢复,我们对这个业务接口做了统一的开关。当再次发布上线时,system cpu time 立即飙高,故障重现了,所以可以断定是由 timestamp 的 time_zone 导致。

再次上线时,观察到 system cpu time 飙高,和故障现象一致

再次上线

为什么在定位到具体原因之前就发布上线呢?因为经过评估即使再次出现问题能通过开关来立即恢复,可控;另外,对于业务而言,即使这期间短暂出现问题在业务接受范围之内,可接受。

原因定位

到底是不是 time_zone 导致,压测一下便知。在线下借助 sysbench 对该 SQL 进行压测(num-threads=30),该问题立即复现。

  • sysbench

压测时,sys cpu time 飙高,sys 飙高到 78%

sys飙高

  • vmstat

上下文切换的次数变化并不大,涨了 10 倍,但运行队列 r 变化比较大,因为是并发压测引起的

上下文切换

  • perf top

通过 perf top 查看热点函数,可以看出_spin_lock是热点,CPU 被内核的 spin lock(自旋锁)占用。

spin情况

  • pstack

通过分析 pstack 获取到的 MySQL 进程的线程堆栈信息,可以发现和 SQL 执行相关的__lll_lock_wait_private()调用量比较大

123456789101112
45 20 #0  0x0000003d6ace1453 in select () from /lib64/libc.so.6
18 #0  0x0000003d6a800614 in ?? () from /lib64/libaio.so.1
17 #0  0x0000003d6acf813e in __lll_lock_wait_private () from /lib64/libc.so.6
 6 #0  0x0000003d6b00b98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 6 #0  0x0000003d6b00b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 5 #0  0x0000003d6acf816f in __lll_unlock_wake_private () from /lib64/libc.so.6
 1 #0  0x0000003d6b00f4b5 in sigwait () from /lib64/libpthread.so.0
 1 #0  0x0000003d6ac9daed in __tz_convert () from /lib64/libc.so.6
 1 #0  0x0000003d6ac33857 in sigwaitinfo () from /lib64/libc.so.6
 1 #0  0x0000000000a51628 in srv_release_threads(srv_thread_type, unsigned long) ()
 1 #0  0x0000000000979cca in start_table_io_wait_v1 ()

为什么不是poll(),select(),??()的问题呢?因为通过分析三个方法的调用栈,可以看出它们分别实现了读取网络包,读取 DB 数据以及异步 IO 相关的功能,和具体的 SQL 并无直接关系,所以可以排除这三个方法的嫌疑

通过分析__lll_lock_wait_private()的调用栈可以发现,在调用__tz_convert ()时会等待获取锁

1234567891011121314151617181920212223242526
  Thread 75 (Thread 0x7fbd155b2700 (LWP 63182)):#0  0x0000003d6acf813e in __lll_lock_wait_private () from /lib64/libc.so.6#1  0x0000003d6ac9dcad in _L_lock_2164 () from /lib64/libc.so.6#2  0x0000003d6ac9da67 in __tz_convert () from /lib64/libc.so.6#3  0x000000000078be27 in Time_zone_system::gmt_sec_to_TIME(st_mysql_time*, long) const ()#4  0x00000000007ce1b7 in Field_timestampf::get_date_internal(st_mysql_time*) ()#5  0x00000000007cb029 in Field_temporal_with_date::val_date_temporal() ()#6  0x00000000005e12d0 in get_datetime_value(THD*, Item*, Item, Item*, bool*) ()#7  0x00000000005d4367 in Arg_comparator::compare_datetime() ()#8  0x00000000005db942 in Item_func_ge::val_int() ()#9  0x00000000005bd1ac in Item::val_bool() ()#10 0x00000000005d670a in Item_cond_and::val_int() ()#11 0x00000000006cc089 in evaluate_join_record(JOIN*, st_join_table*) ()#12 0x00000000006cc8b1 in sub_select(JOIN*, st_join_table*, bool) ()#13 0x00000000006cd11a in JOIN::exec() ()#14 0x0000000000710e10 in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, SQL_I_List<st_order>, SQL_I_List<st_order>, Item*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) ()#15 0x0000000000711697 in handle_select(THD*, select_result*, unsigned long) ()#16 0x00000000006eb60d in execute_sqlcom_select(THD*, TABLE_LIST*) ()#17 0x00000000006ee5db in mysql_execute_command(THD*) ()#18 0x00000000006f2408 in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()#19 0x00000000006f3964 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()#20 0x00000000006bf01f in do_handle_one_connection(THD*) ()#21 0x00000000006bf0f7 in handle_one_connection ()#22 0x000000000097b0ca in pfs_spawn_thread ()#23 0x0000003d6b0079d1 in start_thread () from /lib64/libpthread.so.0#24 0x0000003d6ace89dd in clone () from /lib64/libc.so.6

  1. 修改 time_zone,避免时区转换

修改 time_zone 为’+8:00’ 后再次压测,system cpu time 显示正常。

自此可以确定是 time_zone 导致

解决方案

基本可行的两种解决方案

  • 修改 time_zone

最简单直接的解决方案,但是不适用于对时区敏感的业务系统

1
default-time-zone = '+8:00'

详细讲解 MySQL Time Zone资料

  • 使用 DATETIME

或者统一使用 DATETIME,而不使用 TIMESTAMP,天生无时区转换问题,但是这种方案对现有系统的改造成本巨大

OS 上关于DATETIME VS TIMESTAMP讨论

触发条件

为什么之前未出现这类问题,这次突然出现了呢?经过 DBA 的压测,SQL 的数据读取量在 1K 以下或者 num_threads 在 10 以下均不会出现,当然这个数据还需要结合 MySQL 服务器的硬件配置。所以和数据量以及 MySQL 当时处理有关,随着这张表的数据量的增长,就触发了这次故障。

参考资料

《MySQL 数据库 SYS CPU 高的可能性分析》

No Reply at the moment.
You need to Sign in before reply, if you don't have an account, please Sign up first.