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

某天某客户反馈了一个诡异的问题,一个MySQL实例一会可访问,一会不可访问,查看相关日志发现该实例反复执行高可用切换,为什么会这样呢 ?本文将为大家呈现具体排查过程及原因。

作者 罗小波·沃趣科技高级数据库技术专家
出品 沃趣科技

| 故事背景

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

操作系统: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视图信息。

# 心跳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高可用的心跳检测场景这里,就掉坑里了。


| 作者简介

罗小波·沃趣科技高级数据库技术专家

IT从业多年,历任运维工程师、高级运维工程师、运维经理、数据库工程师,曾参与版本发布系统、轻量级监控系统、运维管理平台、数据库管理平台的设计与编写,熟悉MySQL体系结构,Innodb存储引擎,喜好专研开源技术,追求完美。


发表评论

电子邮件地址不会被公开。 必填项已用*标注