​MySQL 一個讓你懷疑人生的hang死現象

1、故障現象

• 某客戶反饋，在利用binlog日誌的解析內容做基於時間點的恢復時，出現hang死（超過12小時那種），恢復過程無法繼續，而且100%重現
  
  • 基於時間點恢復的實現方式為：使用mysqlbinlog命令指定一個結束時間點，解析binlog並使用管道直接匯入資料庫中執行（例如：mysqlbinlog binlog_file | mysql -uroot -pxx）
• 對此，我們收集了最基本的一些環境資訊（注：這是客戶環境），如下
  
  • 資料庫版本：MySQL 5.7.26
  • 作業系統：CentOS 7.2 x64
  • 伺服器配置：
    * CPU：8 vcpus
    * 磁碟：磁碟陣列
    * 記憶體：16G
  • 資料庫關鍵引數：buffer pool為實體記憶體的一半，row格式複製
  • 資料庫複製拓撲：一主一 從，恢復資料的過程是使用從庫的資料全量快照 + 從庫的binlog實現，恢復目標伺服器是另外一臺單獨的資料庫伺服器，該伺服器只用於臨時恢復資料，不存在複製拓撲，未配置監控或心跳檢測
• 透過簡單的詢問，確認系統負載不高，資料庫也幾乎無負載。綜合這些資訊，在未看到現場之前，我們進行了簡單的推理，認為該hang死現象很可能是由於大事務導致的，所以，我們一上去現場就直接圍繞資料庫進行排查，幾經周折，終於發現了問題的原因，而且也找到了解決問題的方法。但，導致hang死的原因遠沒有想象的那麼簡單，而且具有一定的迷惑性，我們對此進行一個簡單的總結並分享給大家
• PS1：下文中的資料為復現資料，復現的伺服器配置如下（資料庫使用沃趣最佳實踐配置模板）
  
  • CPU：32 vcpus
  • 記憶體：256G
  • 磁碟：1.6T LSI FLASH卡
  • 網路：萬兆網路
• PS2：留意下文程式碼段中的中文註釋

2、分析排查

• 首先，檢視mysqlbinlog程式，可以看到它正在執行著

[root@localhost ~]# ps aux |grep mysqlbinlog
root 27822 1.3 0.0 24568 3204 pts/2 R+ 15:11 0:04 mysqlbinlog --stop-datetime='2019-07-14 16:30:00' mysql-bin.000014 mysql-bin.000015 mysql-bin.000016 mysql-bin.000017 mysql-bin.000018 mysql-bin.000019
......

• 然後，檢視了當前正在執行的執行緒狀態資訊，發現一個sleep長達157269S的執行緒，這是什麼鬼。。大事務未提交嗎？竊喜！

admin@localhost : test 02:18:27> show processlist;
+----+-------+-----------+------+---------+--------+----------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------+-----------+------+---------+--------+----------+------------------+
| 14 | admin | localhost | test | Query | 0 | starting | show processlist |
| 15 | admin | localhost | test | Sleep | 157269 | | NULL |
+----+-------+-----------+------+---------+--------+----------+------------------+
2 rows in set (0.00 sec)

• 接著，我們檢視了事務和鎖資訊

# 先檢視事務資訊
admin@localhost : test 03:02:36> select * from information_schema.innodb_trx\G
Empty set (0.00 sec) # 納尼！！，居然不存在事務正在執行
# 然後檢視鎖資訊
admin@localhost : test 03:30:25> select * from information_schema.innodb_locks;
Empty set, 1 warning (0.00 sec) # WTF！！居然也沒有鎖資訊

• 至此，排查視乎陷入了僵局。既然不存在大事務，也沒有鎖資訊，用於恢復資料的客戶端連線也處於Sleep狀態，那就表示此時資料庫未做任何事情（該資料庫是一個用於資料恢復的臨時庫，並沒有任何其他訪問業務，也並沒有監控、心跳等，只有2個連線，一個是我們登入上去排查問題的連線，另外一個就是使用mysqlbinlog命令恢復資料的客戶端連線），那麼，為什麼會hang？百思不得其解！

• 再接著，我們檢視了一下系統負載，記憶體、網路、磁碟都幾乎無負載，CPU也沒啥負載，但卻有一個奇怪的現象，有一個CPU核心的利用率為100%，如下

top - 15:40:50 up 117 days, 8:09, 5 users, load average: 1.97, 1.36, 1.15
Tasks: 496 total, 2 running, 494 sleeping, 0 stopped, 0 zombie
%Cpu0 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
# 利用率為100%的CPU核心在這裡
%Cpu2 : 34.4 us, 65.6 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu3 : 0.3 us, 0.3 sy, 0.0 ni, 99.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu4 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu5 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu6 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu7 : 0.0 us, 0.0 sy, 0.0 ni,100.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
......

• 最後，在恢復庫中，我們檢視了一下GTID資訊，發現GTID號不連續，少了一個事務的GTID（3759）

admin@localhost : (none) 03:52:08> show master status;
+------------------+----------+--------------+------------------+---------------------------------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+---------------------------------------------+
| mysql-bin.000013 | 500 | | | 5de97c46-a496-11e9-824b-0025905b06da:1-3758,3760-3767 |
+------------------+----------+--------------+------------------+---------------------------------------------+
1 row in set (0.00 sec)

• 透過檢視從庫中的GTID（也就是恢復庫的資料來源對應的庫），並沒有少GTID號為3759的事務，為什麼莫名在恢復庫中會少，而不是連續的？帶著好奇，我們使用該GTID號解析了從庫中的所有被指定用於恢復的binlog file列表（這裡指的就是mysql-bin.000014 mysql-bin.000015 mysql-bin.000016 mysql-bin.000017 mysql-bin.000018 mysql-bin.000019），從這些binlog中提取了GTID號為3759的事務的binlog日誌內容

[root@localhost binlog]# mysqlbinlog mysql-bin.000014 mysql-bin.000015 mysql-bin.000016 mysql-bin.000017 mysql-bin.000018 mysql-bin.000019 --include-gtids='5de97c46-a496-11e9-824b-0025905b06da:3759' > b.sql
[root@localhost binlog]# ls -lh b.sql
-rw-r--r-- 1 root root 996M Jul 14 15:59 b.sql # My God，GTID號為3759的一個事務binlog日誌量快接近一個G了
# 使用mysqlbinlog命令加-vv選項重新解析（使用-vv選項解析，會導致解析結果的大小翻3倍左右），檢視事務的原始語句是怎樣的（binlog_rows_query_log_events=ON才會記錄事務的原始語句文字）
[root@localhost binlog]# mysqlbinlog -vv mysql-bin.000014 mysql-bin.000015 mysql-bin.000016 mysql-bin.000017 mysql-bin.000018 mysql-bin.000019 --include-gtids='5de97c46-a496-11e9-824b-0025905b06da:3759' > c.sql
# vim開啟c.sql檔案檢視
[root@localhost binlog]# ls -lh
total 12G
-rw-r--r-- 1 root root 994M Jul 14 16:38 b.sql
-rw-r--r-- 1 root root 2.7G Jul 14 16:40 c.sql
......
[root@localhost binlog]# vim c.sql
......
# at 336
#190714 16:29:10 server id 3306102 end_log_pos 422 CRC32 0x3b2c9b07 Rows_query
# 發現一個400W行的大事務（經檢視sbtest.sbtest1表中的資料量，確認該語句會往test.sbtest1表中插入400W行）
# insert into sbtest1 select * from sbtest.sbtest1 limit 4000000
......
BINLOG '
1ucqXRN2cjIAOQAAAN8BAAAAAHUAAAAAAAEABHRlc3QAB3NidGVzdDEABAMD/v4E7mj+tABkzbY1
1ucqXR52cjIADSAAAOwhAAAAAHUAAAAAAAAAAgAE//ABAAAAlyomAHcAMzMzNjgzMDQzMTQtMjYx
MDIwNDA4ODktMTU4NzIxODA4NzYtMTU0NDIxOTgxNjQtNDYzOTM1NDIxMzEtMTQwODg3NzUzNTQt
NzY4MDU0ODgyMTEtNzg0ODM1NTU5NjEtNjMyMDM5NjA0ODEtNDcxNjQ5MDg4MjY7NTA3NzUyOTM0
MzctMjE4MzMzNTAzNzYtODc2MTE2NjU0NTYtNjI4NTU3NjAyOTItNDQ3Mjc0MzA4MTjwAwAAAA0z
HQB3ADM4NjUyNzU5NDQwLTg4NjY4MjU5MDE3LTk0MDk4ODI4Nzc1LTYxMzMzNjEwMjg0LTYyODc3
NDgxMTY3LTY1NzM3Mjg3NTExLTA4MDYwNzA5NTU1LTIzMTUyNjI5NTcxLTE2MDMzMDM2NDE5LTYy
MjA0MDgxMzc0OzczOTE3OTQ0NjMzLTc0ODMwMjgwMjE3LTAxMTYzODkwMzkzLTU3NTEzNDA4MDY1
LTMwNjgzOTA1MTQ08AUAAAAlNCYAdwAwMjU2MTIyODQ3MC05OTAwMzk1ODMyOC0zMDQ1OTgyMzQw
NC0zMTY1MTgyNzE4OC02MDMxODU1MDA5OS03Njk5Njk5MTY3Mi02MTI1Nzg5NTU5MC03NDA3OTQz
MDg4MC01NzMyMDA4MzY4NC0zNjAzMDY2NDE4NjszOTA4Nzk4NjM5NC02MjA0NjQ4MDk0Ny01NjQ0
NTE4NzA3My0yODQxNDg5MzQyNC03OTYxOTMzMTg1N/AHAAAAn1MmAHcAODgxMzg4MjkxMjEtMDkx
NTk1NDI1OTctNzc4ODUwODczMzMtMjA1MzE3NDM2MjktODE3NTQ0NDc2MjgtMjczNDMyMzQ2ODEt
...... # 這就是這個大事務對應的BINLOG編碼，整個b.sql檔案的994MB的內容主要就是這些BINLOG編碼

• 分析到這裡，總算是發現了導致MySQL 客戶端hang死的直接原因（注意，是客戶端hang死，不是服務端），即，MySQL客戶端在應用一個400W行大事務的binlog時，導致MySQL客戶端出現hang死。
• 但是，問題又來了，一個400W行的大事務，為什麼會導致客戶端hang死長達12個小時？而且在此期間，資料庫和作業系統的負載並不高，資料庫的各項引數設定也並沒有達到上限，而且，檢視了資料庫的錯誤日誌和作業系統日誌(/var/log/messages)，也並沒有發現任何有用資訊。
• so..，接下來我們就需要進一步分析為何一個大事務會導致客戶端hang死

3、找到罪魁禍首

• 上文中我們提到過，該故障現象可以100%重現，這為我們進一步分析該問題提供了便利。在開始進一步分析之前，我們先列出在不同磁碟裝置的伺服器環境中插入400W行大事務的時間參考資料（經驗值，不精確）
  
  • 假定記憶體和CPU不成瓶頸的情況下
    * 使用15000轉/分的SAS盤時，insert into x select * from y;語句插入400W行資料大約15分鐘內完成
    * 使用普通SSD時，insert into x select * from y;語句插入400W行資料大約5分鐘內完成
    * 使用FLASH卡時，insert into x select * from y;語句插入400W行資料大約3分鐘內完成
• 雖然上述提供的參考時間資料不精確，處理一個大事務的BINLOG編碼也可能有一些額外的開銷，但匯入一個400W行大事務的binlog無論如何都不可能超過12個小時
• so..，接下來，我們將使用strace、pstack等工具，再結合翻看原始碼的方式來排查該問題

3.1. strace 工具排查

• 使用strace工具檢視登入MySQL並載入binlog解析文字過程中的一些輸出資訊（這裡直接使用上文中提到的b.sql）

[root@localhost ~]# strace mysql 2> strace.txt
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 22
Server version: 5.7.26-log MySQL Community Server (GPL)
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
admin@localhost : (none) 10:49:36> use test
Database changed
admin@localhost : test 10:49:38> source /data/mysqldata1/binlog/b.sql;
......
Charset changed
......
Warning (Code 1681): Updating 'collation_database' is deprecated. It will be made read-only in a future release.
Query OK, 0 rows affected (0.00 sec)
# 卡在這裡了，此時你可以先去幹點別的，20分鐘之後再回來看看匯入成功了沒有，不過，不管你等不等，這個客戶端要留著後續排查用，不能斷開了

• 現在，另起一個終端會話，檢視strace.txt檔案中的內容

[root@localhost ~]# tailf strace.txt
......
munmap(0x7f8d6607d000, 58281984) = 0
read(4, "wMjE4ODQzLTE5MTYzMTE4NDk4LTQwNTA"..., 4096) = 4096
mmap(NULL, 58290176, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8d5f150000
...... # 發現不斷地列印類似下面這一段資訊，貌似卡在記憶體分配這裡了
munmap(0x7f8d628e1000, 58298368) = 0
read(4, "UxNzUtODUyMjQ1MTkxMDEtMTM4MTk3OD"..., 4096) = 4096
mmap(NULL, 58306560, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8d66077000
......

• 很無奈，我們使用strace工具在這裡並沒有發現實質性有用資訊，需要使用其他的工具進行排查，現在，你可以關閉用於導數測試的客戶端連線了（注意，使用了strace命令之後，客戶端連線可以立即終止，如果沒有使用strace命令，資料庫的終端會話hang死了，無法終止資料庫的導數操作，別說我沒有等它回滾，我等了好幾個小時...）

• 注意：如果你在跟隨我們的復現過程玩耍，建議你檢視一下show processlist的資訊，你可能會發現之前匯入b.sql檔案的客戶端連線在資料庫中並沒有被斷開，如果發現此情況，則需要在資料庫中手工執行kill操作

admin@localhost : (none) 11:14:54> show processlist;
+----+-------+-----------+------+---------+-------+----------------------------------+----------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------+-----------+------+---------+-------+----------------------------------+----------------------------------------------------------------------+
| 22 | admin | localhost | test | Sleep | 67545 | | NULL |
......
| 32 | admin | localhost | NULL | Query | 0 | starting | show processlist |
+----+-------+-----------+------+---------+-------+----------------------------------+----------------------------------------------------------------------+
admin@localhost : (none) 11:14:55> kill 22;
Query OK, 0 rows affected (0.00 sec)

3.2. pstack 工具排查

• 登入到MySQL並執行匯入b.sql檔案操作（不要用strace）

[root@localhost ~]# mysql -uadmin -ppassword
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 31
Server version: 5.7.26-log MySQL Community Server (GPL)
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
admin@localhost : (none) 11:08:58> use test
Database changed
admin@localhost : test 11:09:00> source /data/mysqldata1/binlog/b.sql;
......

• 使用pstack工具檢視MySQL客戶端連線的程式堆疊資訊

# 檢視MySQL客戶端連線程式號
[root@localhost ~]# ps aux |grep 'mysql -uadmin' |grep -v grep
root 4614 81.2 0.0 175080 41284 pts/21 R+ 11:18 0:20 mysql -uadmin -px xxxx
# 使用pstack工具檢視
[root@localhost ~]# pstack 4614 |tee -a pstack.txt
# 發現它卡在__memmove_ssse3_back ()記憶體複製的階段了。此時你可以看到系統的某一個CPU的idle是0%（與上文中發現的CPU負載詭異現象吻合），這個CPU被耗盡的CPU做的事情就是，持續申請記憶體、複製資料、釋放記憶體，自然把一個CPU給用完了
#0 0x00007f1009f5c315 in __memmove_ssse3_back () from /lib64/libc.so.6
#1 0x0000000000422adf in my_realloc (key=<optimized out>, ptr=0x7f0ffde45030, size=30197464, flags=<optimized out>) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/mysys/my_malloc.c:100
#2 0x000000000041a2ba in String::mem_realloc (this=0xa45460 <glob_buffer>, alloc_length=30197460, force_on_heap=<optimized out>) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/sql-common/sql_string.cc:121
#3 0x0000000000417922 in add_line (truncated=false, ml_comment=<optimized out>, in_string=<optimized out>, line_length=76, line=0x16b4309 "NDQ4NDA0LTE5MjQ2NjgzMDgxLTY2MTA0Mjk0ODQ2LTYzNzk3MjcwMjU0LTQ3NjA2Nzk0MTY0LTEx\nODQwNjExOTY5OzY5NTQ1Mjc5MDA2LTM5NTgwMjUzMDEzLTgzMjQxNjU0MzQ1LTA4MDkxMDEzODk1\nLTk5NzMxMDYyMzU58B2TAwABKiYAdwAwNTEzMjEzNDUzNC"..., buffer=...) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:2795
#4 read_and_execute (interactive=false) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:2364
#5 0x00000000004181ef in com_source (buffer=<optimized out>, line=<optimized out>) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:4709
#6 0x0000000000417099 in add_line (truncated=false, ml_comment=<optimized out>, in_string=<optimized out>, line_length=37, line=0x16b2a10 "source /data/mysqldata1/binlog/b.sql;", buffer=...) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:2664
#7 read_and_execute (interactive=true) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:2364
#8 0x0000000000418c98 in main (argc=15, argv=0x160c348) at /export/home/pb2/build/sb_0-33648028-1555164244.06/mysql-5.7.26/client/mysql.cc:1447

• 開心，使用pstack工具發現了一個較為有用的資訊，從這裡我們知道了MySQL客戶端在匯入b.sql時，卡在了使用__memmove_ssse3_back ()函式做記憶體複製的階段了
• 那麼問題又來了，為什麼會卡在這裡？結合上述獲取到的資訊，我們知道，MySQL客戶端只是與服務端建立了一個連線，後續服務端沒有收到任何資訊（也就是整個客戶端hang死期間，服務端沒有做任何事情），so..，接下來我們必須要去翻閱原始碼來尋找答案了：為什麼MySQL客戶端會卡在 __memmove_ssse3_back ()函式記憶體複製階段？

3.3. 翻閱客戶端命令mysql的原始碼排查

• 由於是在MySQL 5.7.26版本中發生的故障，所以我們首先檢視了MySQL 5.7.26版本的客戶端原始碼，MySQL客戶端在讀取一個檔案時（或者說判斷什麼時候可以將一個操作傳送給服務端時），碰到';'分號會直接將前面讀取到的內容作為一整個資料包丟給服務端，對上文中提到的b.sql檔案中的BINLOG編碼，整個BINLOG編碼只有一個分號，所以會等到整個BINLOG編碼讀取完成之後才會傳送給服務端，在讀取這個超大BINLOG編碼的過程中，MySQL客戶端會一行一行的讀，並記錄到global_buffer中。當global_buffer申請的空間不足時，就需要擴充套件記憶體空間，，擴充套件記憶體空間的程式碼如下：

// client/mysql.cc 檔案
    if (buffer.length() + length >= buffer.alloced_length())
      buffer.mem_realloc(buffer.length()+length+IO_SIZE); # 每次除了擴充套件不夠的記憶體以外（原有的記憶體長度+新讀取的內容長度），額外只多擴充套件了4k的空間（也就是IO_SIZE，IO_SIZE變數的定義大小詳見程式碼段後續的"include/my_global.h 檔案"）
// mysys/my_malloc.c 檔案
  new_ptr= my_malloc(key, size, flags); # 擴充套件記憶體時先申請一段新的更大空間的記憶體（新申請的一段記憶體的大小為client/mysql.cc 檔案中描述的擴充套件之後的記憶體大小）
  if (likely(new_ptr != NULL))
  {
#ifndef DBUG_OFF
    my_memory_header *new_mh= USER_TO_HEADER(new_ptr);
#endif
    DBUG_ASSERT((new_mh->m_key == key) || (new_mh->m_key == PSI_NOT_INSTRUMENTED));
    DBUG_ASSERT(new_mh->m_magic == MAGIC);
    DBUG_ASSERT(new_mh->m_size == size);
    min_size= (old_size < size) ? old_size : size;
    memcpy(new_ptr, ptr, min_size); # 然後把資料複製過去
    my_free(ptr);
    return new_ptr;
  }
// include/my_global.h 檔案
#define OS_FILE_LIMIT UINT_MAX
/*
  Io buffer size; Must be a power of 2 and a multiple of 512. May be
  smaller what the disk page size. This influences the speed of the
  isam btree library. eg to big to slow.
*/
#define IO_SIZE 4096 # IO_SIZE 變數的大小定義為4K

• 透過翻閱原始碼中的相關程式碼，再結合b.sql中400W行大事務產生的BINLOG編碼，我們可以得出如下結論：
  • MySQL客戶端讀取b.sql檔案中的BINLOG編碼時，會把整個BINLOG編碼當做一整個資料包對待，也就是說客戶端先要將其完整讀取並存放在記憶體中，然後再將其作為一整個資料包傳送給服務端（包的大小由客戶端和服務端的max_allowed_packet引數共同控制，以最小的為準），客戶端在讀取BINLOG編碼的過程中，每讀一行都會先判斷原先分配的記憶體是否足夠，如果記憶體不足就需要擴充套件一下，申請新的一段記憶體，並且把原來的記憶體中的資料複製過去（新申請的記憶體），自然就非常慢，看上去就好像客戶端hang死一樣，而客戶端讀取BINLOG編碼的整個過程中，服務端都沒有收到任何的操作，所以，從服務端的show processlist看到執行緒狀態一直是Sleep狀態，也沒有事務，也沒有鎖資訊。
  • 也就是說，這裡可以排除掉mysqlbinlog命令解析binlog的嫌疑

4、幹掉罪魁禍首

• 雖然，我們發現了問題的根本原因，是因為MySQL客戶端讀取大事務的BINLOG編碼時分配記憶體的效率太低導致的，但是，怎麼解決它呢？改程式碼？怎麼改？改了出其他問題咋辦？
• IO_SIZE變數是一個比較底層的變數，不同用途的buffer分配都會使用該變數作為一個基準參考，所以不能直接修改此變數的大小。因此，我們並沒有急於去修改客戶端程式碼，而是先嚐試使用MySQL 8.0.16、MariaDB 10.1.40/10.2.25/10.3.16/10.4.6、Percona Server 5.7.26進行測試，發現如下現象
  
  • MySQL 5.7.x和Percona Server 5.7.x：表現一致，客戶端hang死
  • MySQL 8.0.x：在兩三分鐘之後，客戶端連線被服務端斷開
  • MariaDB：表現與MySQL 8.0.x一致
• 那麼，問題又雙叒叕來了
  
  • 1）、為什麼MariaDB和MySQL 8.0.x會將客戶端連線斷開，而不像MySQL 5.7.x和Percona Server 5.7.x那樣導致MySQL客戶端hang死
  • 2）、MySQL 8.0.x在MySQL 5.7.x的基礎上做了什麼改動使得他們在匯入相同資料時的表現不同呢？
• 我們先解決第一個問題（我想大多數人也是這麼想的，對吧），過程很辛酸，最後發現一個很low的問題，就是。。服務端的max_allowed_packet系統變數值設定太小了（64M），將其改為1G之後
  
  • 在MariaDB和MySQL 8.0.x中，這個400W行的大事務產生的binlog可以在3分鐘以內應用完成（注意，該引數最大值為1G，如果你的事務產生的BINLOG編碼長度大於該引數，則仍然會被服務端斷開連線）
  • 在MySQL 5.7.x和Percona Server 5.7.x版本中修改該引數為1G之後，也可以應用完成，只是要差不多2天左右的時間，這跟hang死沒什麼兩樣，所以問題並沒有解決（因為客戶使用的是MySQL 5.7.26版本嘛...）

• 接下來，我們解決第二個問題，比對MySQL 5.7.26和MySQL 8.0.16版本中，關於客戶端快取讀取檔案資料這塊的記憶體分配程式碼有什麼不同？

# 以下只列出MySQL 8.0.16版本中的程式碼
// client/mysql.cc 檔案
    if (buffer.length() + length >= buffer.alloced_length())
      buffer.mem_realloc(buffer.length() + length + batch_io_size); ## 8.0中每次擴記憶體時，額外分配的記憶體大小變更為了batch_io_size，在5.7中，batch_io_size位置是IO_SIZE
// client/my_readline.h 檔案
static const unsigned long int batch_io_size = 16 * 1024 * 1024; ## 這裡定義batch_io_size為16M，從4K變為16M，這就使得客戶端在快取讀取的資料時，發現記憶體不夠之後的記憶體分配效率提高几個數量級

• so...看起來，需要怎麼修改MySQL的客戶端程式碼已經很清晰了，只需要新定義一個batch_io_size變數，然後將'buffer.mem_realloc(buffer.length()+length+IO_SIZE)' 修改為'buffer.mem_realloc(buffer.length() + length + batch_io_size)'即可
• 說幹就幹，我們按照此結論對MySQL的客戶端mysql的原始碼進行了修改，重新編譯，然後，將服務端和客戶端的max_allowed_packet引數都設定為1G，重新匯入400W行的大事務產生的row格式binlog（即，使用insert into sbtest1 select * from sbtest.sbtest1 limit 4000000  語句產生的row格式binlog解析文字進行測試），3分鐘內完成了匯入，至此，問題解決！

• 最後，多說一句，MariaDB雖然也同樣解決了這個問題，但是解決方法完全不同（粗略看了一下程式碼，沒細看），透過比對解析的BINLOG編碼，發現MariaDB的BINLOG編碼是存在一個個的空缺，所以猜測可能是採用了"mysqlbinlog的解析格式變更"配合"mysql客戶端的解析邏輯變更"來解決該問題的（MariaDB在執行匯入binlog解析內容時，show processlist檢視執行緒狀態也能發現匯入資料的執行緒一直在幹活，並不是一直處於Sleep狀態），類似如下

  • MariaDB  
    * BINLOG編碼格式

    
    * show processlist狀態

    
    

  • MySQL 

    * BINLOG編碼格式

    * show processlist狀態 

    

| 作者簡介

羅小波·沃趣科技高階資料庫技術專家

IT從業多年，主要負責MySQL 產品的資料庫支撐與售後二線支撐。曾參與版本釋出系統、輕量級監控系統、運維管理平臺、資料庫管理平臺的設計與編寫，熟悉MySQL體系結構，Innodb儲存引擎，喜好專研開源技術，多次在公開場合做過線下線上資料庫專題分享，發表過多篇資料庫相關的研究文章。