利用sys schema解决一次诡异的语句hang问题-白红宇

利用sys schema解决一次诡异的语句hang问题

阅读量：2446 次

发布时间：2019-05-10

本文共 15641 字，大约阅读时间需要 52 分钟。

沃趣科技罗小波

导读

1、故事背景

在开始之前，先列出数据库的运行环境信息
- 操作系统：redhat 7.2 x8_64
- 文件系统：xfs
- 数据库版本：MySQL 5.7.17
- 主机配置：
  * CPU：32 vcpus
  * 内存：128 G
  * 磁盘：单盘intel SSD 320G（只存放mysql的data和binlog）
- 主要配置参数设置：innodb_buffer_pool_size = 96G，innodb_log_file_size = 2G，innodb_flush_method = O_DIRECT，sync_binlog = 1，innodb_flush_log_at_trx_commit = 1，innodb_thread_concurrency = 32,innodb_io_capacity = 20000，innodb_read_io_threads = 4，innodb_write_io_threads = 12，transaction_isolation = READ-COMMITTED，performance_schema=ON，binlog_rows_query_log_events=ON
- 该实例接入了高可用机制：HA心跳探测机制60S内发现实例持续探测失败时（每5秒探测一次），直接尝试关闭探测失败的MySQL实例和主机，进行高可用切换

故事情节：
- 前些天某客户反馈一个诡异的问题，一个MySQL实例一会可访问，一会不可访问，查看相关日志发现该实例反复执行高可用切换，在进行初略排查时，通过监控发现服务器故障时刻磁盘负载都较高，但是并没有完全用满。而在高可用切换之前，数据库中跑着一些insert…select语句和大量心跳检测语句，而心跳检测语句与业务表是独立的，且心跳检测语句只固定更新一行数据，怎么会被阻塞一堆心跳检测语句呢？经过了一番折腾总算把原因找到了，具体过程请看下文！

2、复现与剖析

经过初略的分析，虽然业务SQL和心跳SQL操作的是不同的表，不会出现锁等待问题，但是从show processlist;的结果来看，业务SQL执行时间最长，而且不断有新的心跳语句被阻塞（当然，这里要先关掉HA的切换机制，否则待会复现操作时，过了60S就可能被切换了），看起来阻塞心跳SQL的很可能就是业务SQL。而且这些业务SQL操作的数据量多达3千万行（因为是insert…select语句，所以从慢日志或者innodb_trx表、sys.session视图中查看到的数据量实际上多达6KW，翻倍了）。但是两者之间有具体有什么关联无法直观地看出来。我们按照如下步骤进行了复现：

2.1. 首先按照线上环境标准准备好复现环境，搭建了一台测试机

2.2. 创建一张心跳表，插入一行数据

点击(此处)折叠或打开

root@localhost :test:33: > CREATE TABLE `xx_heartbeat` (

`server_id` int(10) unsigned NOT NULL,

`hb_time` datetime NOT NULL,

PRIMARY KEY (`server_id`)

) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin;

root@localhost :test:33: > insert into xx_heartbeat values(@@server_id,now());

root@localhost :test:33: > select * from xx_heartbeat;

+-----------+---------------------+

| server_id | hb_time |

+-----------+---------------------+

| 3306103 | 2017-10-11 12:33:26 |

+-----------+---------------------+

2 rows in set (0.00 sec)

2.3. 打开performance_schema中的等待事件采集(为了省事，这里使用sys schema下的函数操作，而不使用UPDATE语句直接修改performance_schema的配置表)

点击(此处)折叠或打开

root@localhost :test:34: > use sys

Database changed

root@localhost : sys:36: > call ps_setup_enable_instrument('wait');

+-------------------------+

| summary |

+-------------------------+

| Enabled 303 instruments |

+-------------------------+

1 row in set (0.04 sec)

Query OK, 0 rows affected (0.04 sec)

root@localhost : sys:36: > call ps_setup_enable_consumer('wait');

+---------------------+

| summary |

+---------------------+

| Enabled 3 consumers |

+---------------------+

1 row in set (0.01 sec)

Query OK, 0 rows affected (0.01 sec)

2.4. 开4个MySQL会话连接，依次对4张不同的表执行insert…select操作，表数据量都为3KW（测试数据为使用sysbench造的4张3KW数据的表）

点击(此处)折叠或打开

# 会话1

ADMIN@127.0.0.1 : (none):15: > use sbtest;

Database changed

ADMIN@127.0.0.1 : sbtest:37: > insert sbtest1(k,c,pad) select k,c,pad from sbtest1;

# 会话2

ADMIN@127.0.0.1 : (none):15: > use sbtest;

Database changed

ADMIN@127.0.0.1 : sbtest:37: > insert sbtest3(k,c,pad) select k,c,pad from sbtest3;

# 会话3

ADMIN@127.0.0.1 : (none):18: > use sbtest;

Database changed

ADMIN@127.0.0.1 : sbtest:37: > insert sbtest2(k,c,pad) select k,c,pad from sbtest2;

# 会话4

ADMIN@127.0.0.1 : (none):18: > use sbtest;

Database changed

ADMIN@127.0.0.1 : sbtest:37: > insert sbtest4(k,c,pad) select k,c,pad from sbtest4

2.5. 对心跳表进行更新，持续间隔每5秒一次执行，数十分钟之后，发现心跳SQL被阻塞了，如果HA切换机制没关，阻塞心跳SQL超过60S就会发生切换了，关闭HA切换机制之后，自动心跳会停止检测，所以这里人工模拟了一条心跳SQL，使用脚本循环每5秒更新一次，脚本在发现有阻塞时也会同时打印show processlist和sys.session视图信息，脚本链接： )

点击(此处)折叠或打开

# 心跳SQL语句（可手工每5秒执行这句，不过肯定手会酸。。不过为了方便大家阅读，在复现过程中采用了用脚本持续检测，发现有语句阻塞时立即手工方式执行心跳语句，以方便截取）

ADMIN@127.0.0.1 :test:01: > update xx_heartbeat set hb_time=now() where server_id=@@server_id;

Query OK, 0 rows affected (0.00 sec)

Rows matched: 1 Changed: 0 Warnings: 0

ADMIN@127.0.0.1 :test:01: > update xx_heartbeat set hb_time=now() where server_id=@@server_id

2.6. 立即新开一个会话连接查看数据库正在做什么，可以发现4个会话的insert…select语句，以及心跳SQL update xx_heartbeat…

点击(此处)折叠或打开

ADMIN@127.0.0.1 : sys:25: > show processlist;

+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+

| Id | User | Host | db | Command | Time | State | Info |

+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+

| 25 | ADMIN | 127.0.0.1:35458 | sys | Query | 0 | starting | show processlist |

| 26 | ADMIN | 127.0.0.1:35459 | sbtest | Query | 1353 | query end | insert sbtest1(k,c,pad) select k,c,pad from sbtest1 |

| 27 | ADMIN | 127.0.0.1:35460 | sbtest | Query | 1352 | query end | insert sbtest3(k,c,pad) select k,c,pad from sbtest3 |

| 30 | ADMIN | 127.0.0.1:35463 | sbtest | Query | 1352 | query end | insert sbtest2(k,c,pad) select k,c,pad from sbtest2 |

| 31 | ADMIN | 127.0.0.1:35464 | sbtest | Query | 1351 | query end | insert sbtest4(k,c,pad) select k,c,pad from sbtest4 |

| 52 | ADMIN | 127.0.0.1:35485 | test | Query | 62 | query end | update xx_heartbeat set hb_time=now() where server_id=@@server_id |

| 151 | qfha | 10.10.40.167:51328 | NULL | Query | 562 | starting | SHOW BINARY LOGS |

......

| 160 | qfha | 10.10.40.167:51337 | NULL | Query | 22 | starting | SHOW BINARY LOGS |

+-----+-------+--------------------+--------+---------+------+-----------+----------------------------------------------------------------------+

16 rows in set (0.00 sec)

2.7. 查看服务器负载情况怎样

点击(此处)折叠或打开

# top

top - 22:51:21 up 3 days, 6:54, 9 users, load average: 5.74, 3.39, 1.70

Tasks: 980 total, 1 running, 979 sleeping, 0 stopped, 0 zombie

Cpu(s): 0.4%us, 0.4%sy, 0.0%ni, 97.3%id, 1.9%wa, 0.0%hi, 0.0%si, 0.0%st

Mem: 131804428k total, 129297568k used, 2506860k free, 282052k buffers

Swap: 7974908k total, 106080k used, 7868828k free, 33743992k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

22080 mysql 20 0 86.1g 71g 12m S 23.8 57.0 602:42.90 mysqld

29121 qemu 20 0 17.5g 8.2g 6160 S 6.9 6.5 140:51.21 qemu-kvm

20475 root 20 0 0 0 0 S 0.7 0.0 0:28.71 xfs-cil/dm-6

18272 root 20 0 15692 1952 924 R 0.3 0.0 0:00.33 top

1 root 20 0 19356 1408 1228 S 0.0 0.0 0:02.14 init

2 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kthreadd

3 root RT 0 0 0 0 S 0.0 0.0 0:00.28 migration/0

......

# free

#free -m

total used free shared buffers cached

Mem: 128715 121616 7099 0 275 28429

-/+ buffers/cache: 92911 35803

Swap: 7787 88 7699

# vmstat

[root@10-10-66-229 ~]# vmstat 1 10

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

r b swpd free buff cache si so bi bo in cs us sy id wa st

2 1 90392 2484712 281996 33758712 0 0 0 266326 14803 19717 9 1 87 3 0

7 1 90392 2454332 281996 33787004 0 0 0 263063 14746 18893 10 1 87 2 0

4 10 90392 2427820 281996 33814484 0 0 0 266977 13522 18440 10 1 87 2 0

4 0 90392 2399888 281996 33840928 0 0 0 254064 14727 18820 10 1 87 2 0

4 1 90392 2373260 281996 33865532 0 0 0 255281 15479 19072 10 0 88 2 0

4 1 90392 2344072 281996 33894036 0 0 16 261650 13296 18970 10 0 87 2 0

5 0 90392 2316840 281996 33920892 0 0 0 253947 12292 18442 10 1 88 2 0

4 0 90392 2289436 281996 33947748 0 0 0 273755 13894 19790 10 1 87 3 0

4 0 90392 2258064 281996 33977544 0 0 0 265602 12351 18488 10 0 87 2 0

5 1 90392 2230940 281996 34005292 0 0 0 269967 12720 19439 9 0 88 2 0

......

# iostat

[root@10-10-66-229 ~]# vmstat -x 1 10

......

avg-cpu: %user %nice %system %iowait %steal %idle

10.28 0.00 0.50 2.51 0.00 86.72

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util

sdc 0.00 1031.00 0.00 6041.00 0.00 537654.00 89.00 13.20 2.19 0.16 94.10

......

avg-cpu: %user %nice %system %iowait %steal %idle

9.83 0.00 0.53 2.54 0.00 87.10

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util

sdc 0.00 891.00 0.00 6034.00 0.00 524171.00 86.87 12.78 2.12 0.16 94.70

......

2.8. 从2.6与2.7步骤中查看到的信息来说，服务器的CPU和内存并不是瓶颈，磁盘负载虽然较高且偶尔会用到swap且有2~3%左右的IOWAIT，但是也不至于完全堵死一条单行更新的心跳SQL，而且业务SQL与心跳SQL是不同的表，也不存在表锁和事务锁相互阻塞的问题（使用sys.innodb_lock_waits视图查过，锁等待信息为空）。而从mysql的show processlist信息来看，看不出这些SQL有什么关联，只能看到这些SQL处于query end的状态时间比较长，明显不正常，另外还有一些show binary logs语句，该语句是监控系统监控binlog的大小使用的语句，而且这个语句不断增多，看起来像是binlog的访问出现了问题

2.9. 这个时候，通常使用的排查手段已经相形见拙了，我们启用sys schema，新开一个会话连接，使用session视图来查查这些活跃会话正在执行的SQL到底正在做什么?

点击(此处)折叠或打开

ADMIN@127.0.0.1 : sys:25: > select * from session where conn_id!=connection_id()\G;

*************************** 1. row ***************************

thd_id: 60

conn_id: 26

user: ADMIN@127.0.0.1

db: sbtest

command: Query

state: query end

time: 6355

current_statement: insert sbtest1(k,c,pad) select k,c,pad from sbtest1 # 操作sbtest1表的业务SQL

statement_latency: 22.58 m

progress: NULL

lock_latency: 1.25 ms

rows_examined: 60000000

rows_sent: 0

rows_affected: 0

tmp_tables: 1

tmp_disk_tables: 1

full_scan: YES

last_statement: NULL

last_statement_latency: NULL

current_memory: 0 bytes

last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done # 发现连接ID为26的会话执行insert...select语句时在等待这个事件(binlog的COND_done互斥对象)

last_wait_latency: Still Waiting #该字段值为"Still Waiting"表示这个线程目前一直在等待last_wait字段显示的事件

source: binlog.cc:1949 #发生等待事件的源码文件和代码行数在这里

trx_latency: NULL

trx_state: NULL

trx_autocommit: NULL

pid: 4571

program_name: mysql

*************************** 2. row ***************************

thd_id: 61

conn_id: 27

......

current_statement: insert sbtest3(k,c,pad) select k,c,pad from sbtest3

statement_latency: 22.57 m

......

last_wait: wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log # 发现连接ID为27的会话执行insert...select语句时在等待这个事件（binlog的LOCK_log互斥锁）

last_wait_latency: Still Waiting # 解释同第一行信息相同字段

source: binlog.cc:8587 # 解释同第一行信息相同字段

......

*************************** 3. row ***************************

thd_id: 64

conn_id: 30

......

current_statement: insert sbtest2(k,c,pad) select k,c,pad from sbtest2 #操作sbtest2表的业务SQL

statement_latency: 22.57 m

......

last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done # 发现连接ID为30的会话执行insert...select语句时在等待这个事件(binlog的COND_done对象)

last_wait_latency: Still Waiting # 解释同第一行信息相同字段

source: binlog.cc:1949 # 解释同第一行信息相同字段

......

*************************** 4. row ***************************

thd_id: 65

conn_id: 31

user: ADMIN@127.0.0.1

db: sbtest

command: Query

state: query end

time: 6353

current_statement: insert sbtest4(k,c,pad) select k,c,pad from sbtest4 #操作sbtest4表的业务SQL

statement_latency: 22.55 m

progress: NULL

lock_latency: 1.55 ms

rows_examined: 60000000

rows_sent: 0

rows_affected: 0

tmp_tables: 1

tmp_disk_tables: 1

full_scan: YES

last_statement: NULL

last_statement_latency: NULL

current_memory: 0 bytes

# 发现连接ID为31的会话执行insert...select语句时在等待这个事件(正在执行binlog的文件IO操作，说明在写binlog cache到binlog file，但这里只是写到文件系统的buffer，并不是sync)

last_wait: wait/io/file/sql/binlog

last_wait_latency: Still Waiting # 解释同第一行信息相同字段

source: mf_iocache.c:1566 # 解释同第一行信息相同字段

trx_latency: NULL

trx_state: NULL

trx_autocommit: NULL

pid: 4881

program_name: mysql

......

*************************** 5. row ***************************

thd_id: 185

conn_id: 151

user: qfha@10.10.40.167

db: sys

command: Query

state: starting

time: 564

current_statement: SHOW BINARY LOGS

statement_latency: 9.40 m

progress: NULL

lock_latency: 0 ps

rows_examined: 0

rows_sent: 0

rows_affected: 0

tmp_tables: 0

tmp_disk_tables: 0

full_scan: NO

last_statement: NULL

last_statement_latency: NULL

current_memory: 0 bytes

last_wait: wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_log

last_wait_latency: Still Waiting

source: rpl_master.cc:707

trx_latency: NULL

trx_state: NULL

trx_autocommit: NULL

pid: NULL

program_name: NULL

*************************** 6. row ***************************

......

*************************** 11. row ***************************

thd_id: 86

conn_id: 52

user: ADMIN@127.0.0.1

db:test

command: Query

state: query end

time: 244

current_statement: update xx_heartbeat set hb_ ... () where server_id=@@server_id #操作心跳表的SQL

statement_latency: 1.07 m

progress: NULL

lock_latency: 219.00 us

rows_examined: 1

rows_sent: 0

rows_affected: 0

tmp_tables: 0

tmp_disk_tables: 0

full_scan: NO

last_statement: NULL

last_statement_latency: NULL

current_memory: 0 bytes

last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done # 发现连接ID为52的会话执行心跳SQL语句时在等待这个事件

last_wait_latency: Still Waiting # 解释同第一行信息相同字段

source: binlog.cc:1949 # 解释同第一行信息相同字段

trx_latency: NULL

trx_state: NULL

trx_autocommit: NULL

pid: 6772

program_name: mysql

*************************** 12. row ***************************

......

15 rows in set (0.15 sec)

2.10. 从2.9步骤中的信息来看，基本可以确定是因为写binlog不能及时响应的问题导致的，但是具体是binlog的什么问题呢？跟心跳SQL被阻塞又有什么关系？这个时候我们在以上所有SQL正常执行完成之后（等待时间大约几分钟，超过了60S的高可用切换时间），解析了包含以上业务SQL和心跳SQL的所有binlog文件进行分析（binlog大约有22G），查看这些语句的提交先后顺序，发现都是在同一个group 里，并且心跳SQL排在了业务SQL最后面，详情如下：

点击(此处)折叠或打开

[root@10-10-66-229 binlog]# mysqlbinlog -vv mysql-bin.000175|grep -E 'insert sbtest|insert into sbtest|last_committed|update xx_heartbeat|GTID_NEXT' > a.sql

[root@10-10-66-229 binlog]# cat a.sql

......

#171011 15:01:42 server id 3306103 end_log_pos 29975 CRC32 0x85a80516 GTID last_committed=76 sequence_number=77

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90292'/*!*/;

# update xx_heartbeat set hb_time=now() where server_id=@@server_id

#171011 15:01:43 server id 3306103 end_log_pos 30366 CRC32 0x14c9d915 GTID last_committed=77 sequence_number=78

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90293'/*!*/;

# update xx_heartbeat set hb_time=now() where server_id=@@server_id

# 以下就是我们要找的关键信息，留意记录group 信息的event的时间，从这里可以看到insert...select语句发生的时间顺序按照表名排序\

# 依次sbtest1、sbtest3、sbtest2、sbtest4，xx_heartbeat表（与在客户端敲下SQL的时间顺序相同），从信息"last_committed=78"我们可以知道这些SQL都被放进了\

# 同一个队列里进行binlog提交，从信息"sequence_number=79"我们可以得知，操作表sbtest4的线程在binlog提交队列中的顺序最靠前，也就是说它是leader，其他的为follower

#171011 14:39:56 server id 3306103 end_log_pos 30757 CRC32 0xb2c44222 GTID last_committed=78 sequence_number=79

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90294'/*!*/;

# insert sbtest4(k,c,pad) select k,c,pad from sbtest4 # 业务SQL

#171011 14:39:55 server id 3306103 end_log_pos 1429482395 CRC32 0x00c7685d GTID last_committed=78 sequence_number=80

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90295'/*!*/;

# insert sbtest3(k,c,pad) select k,c,pad from sbtest3 # 业务SQL

#171011 14:39:55 server id 3306103 end_log_pos 2858934033 CRC32 0xb0e9f488 GTID last_committed=78 sequence_number=81

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90296'/*!*/;

# insert sbtest2(k,c,pad) select k,c,pad from sbtest2 # 业务SQL

#171011 14:39:54 server id 3306103 end_log_pos 4288385671 CRC32 0x52cf3dfa GTID last_committed=78 sequence_number=82

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90297'/*!*/;

# insert sbtest1(k,c,pad) select k,c,pad from sbtest1 # 业务SQL

#171011 16:21:45 server id 3306103 end_log_pos 1422870013 CRC32 0xd3caff89 GTID last_committed=78 sequence_number=83

SET @@SESSION.GTID_NEXT= '6d362bfe-ae21-11e7-a22f-fabb9a69be00:90298'/*!*/;

# 下面一句SQL即为被阻塞的心跳SQL，可以看到排在了前面几个业务SQL的后面，而前面几个业务SQL产生了大量的binlog数据，这些数据写到binlog文件中消耗了大量的时间\

# 而因为这句心跳SQL与前面几个业务SQL在同一个group中，必须等待前面几个业务SQL的binlog数据写完之后才能写binlog，所以，从这里就可以知道，\

# 心跳SQL就是因为在提交binlog阶段被业务SQL阻塞了，所以最终导致心跳SQL的事务无法提交

# update xx_heartbeat set hb_time=now() where server_id=@@server_id

SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/

PS：到这里，我们已经知道了心跳SQL被阻塞的原因，但是在2.9步骤中，session视图输出行的last_wait列显示的事件代表什么含义呢？感兴趣的同学可以根据2.9步骤中信息行的source列值翻看源码

3、解决方法

关于碰到类似的因为写binlog时互斥的原因导致毫不相干的表语句相互阻塞的问题的解决方法，需要自行根据业务需求进行分析，这里由于阻塞的是心跳SQL，而HA高可用程序依赖于心跳SQL的检测结果，对这个心跳SQL具有响应时间要求，必须按时返回结果，对于我们演示的这个场景而言，心跳SQL的作用就是检测MySQL实例是否存活、是否可写。so，对于心跳SQL的DML，记录binlog不是必须的，所以我们临时的解决办法就是：动态关闭心跳语句记录BINLOG的功能，就不会因为写binlog的原因被阻塞了，如下：

点击(此处)折叠或打开