利用sys schema解決一次詭異的語句hang問題

2024-09-07 22:12:41

字體：大中小

來源：轉載

供稿：網友

導讀
1、故事背景
2、復現與剖析
3、解決方法
4、總結
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
    [email protected] : (none):15: > use sbtest;
    Database changed
    [email protected] : sbtest:37: > insert sbtest1(k,c,pad) select k,c,pad from sbtest1;
    # 會話2
    [email protected] : (none):15: > use sbtest;
    Database changed
    [email protected] : sbtest:37: > insert sbtest3(k,c,pad) select k,c,pad from sbtest3;
    # 會話3
    [email protected] : (none):18: > use sbtest;
    Database changed
    [email protected] : sbtest:37: > insert sbtest2(k,c,pad) select k,c,pad from sbtest2;
    # 會話4
    [email protected] : (none):18: > use sbtest;
    Database changed
    [email protected] : 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秒執行這句，不過肯定手會酸。。不過為了方便大家閱讀，在復現過程中采用了用腳本持續檢測，發現有語句阻塞時立即手工方式執行心跳語句，以方便截取）
    [email protected] :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
    [email protected] :test:01: > update xx_heartbeat set hb_time=now() where server_id=@@server_id
2.6. 立即新開一個會話連接查看數據庫正在做什么，可以發現4個會話的insert…select語句，以及心跳SQL update xx_heartbeat…
點擊(此處)折疊或打開

[email protected] : 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到底正在做什么?
點擊(此處)折疊或打開

[email protected] : sys:25: > select * from session where conn_id!=connection_id()/G;
    *************************** 1. row ***************************
                    thd_id: 60
                  conn_id: 26
                      user: [email protected]
                        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: [email protected]
                        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: [email protected]
                        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: [email protected]
                        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的原因被阻塞了，如下：
點擊(此處)折疊或打開

set sql_log_bin=0;update xx_heartbeat set hb_time=now() where server_id=@@server_id
4、總結
對于大事務的DML操作，從數據庫的兩大關鍵性能指標(并發數和響應時間)上考慮，強烈建議拆分數據量(例如使用limit按id進行拆分或者程序拆分)，雖然我們的開發規范上一再強調，但對于某些人來講，他就認為慢點無所謂嘛，所以，在HA高可用的心跳檢測場景這里，就掉坑里了。

（編輯：武林網）

上一篇：Docker，讓數據庫布局完成在彈指一揮間

下一篇：按 user 分組統計視圖全方位認識 sys 系統庫