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

沃趣科技發表於2019-10-07

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狀態 

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/28218939/viewspace-2658974/,如需轉載,請註明出處,否則將追究法律責任。

相關文章