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

一、故事背景

在开始之前，先列出数据库的运行环境信息

操作系统：redhat 7.2 x8_64

文件系统：xfs

数据库版本：MySQL 5.7.17

主机配置： 
* CPU：32 vcpus 
* 内存：128 G 
* 磁盘：sandisk 单盘 SSD lvm 200G（只存放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语句和大量心跳检测语句，而心跳检测语句与业务表是独立的，且心跳检测语句只固定更新一行数据，怎么会被阻塞一堆心跳检测语句呢 ？经过了一番折腾总算把原因找到了，具体过程请看下文。

二、复现与剖析

经过初略的分析，虽然业务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视图信息，脚本链接：http://5d096a11.wiz03.com/share/s/1t2mEh0a-kl_2c2NZ33kSiac2wQRmx1ykAEE23yLIT3aKVmx)

# 心跳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                                                ......

# memory

#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列值翻看源码

三、解决方法

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

set sql_log_bin=0;update xx_heartbeat set hb_time=now() where server_id=@@server_id;

四、总  结

对于大事务的DML操作，从数据库的两大关键性能指标(并发数和响应时间)上考虑，强烈建议拆分数据量(例如使用limit按id进行拆分或者程序拆分)，虽然我们的开发规范上一再强调，但对于某些人来讲，他就认为慢点无所谓嘛，所以，在HA高可用的心跳检测场景这里，就掉坑里了。