數據庫

?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進程,可以看到它正在運行著
[[email protected] ~]# 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的線程,這是什么鬼。。大事務未提交嗎?竊喜!
[email protected] : 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)
  • 接著,我們查看了事務和鎖信息
# 先查看事務信息
[email protected] : test 03:02:36> select * from information_schema.innodb_trx\G
Empty set (0.00 sec) # 納尼!!,居然不存在事務正在運行
# 然后查看鎖信息
[email protected] : 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)
[email protected] : (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日志內容
[[email protected] 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
[[email protected] 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才會記錄事務的原始語句文本)
[[email protected] 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文件查看
[[email protected] 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
......
[[email protected] 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)
[[email protected] ~]# 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.
[email protected] : (none) 10:49:36> use test
Database changed
[email protected] : 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文件中的內容
[[email protected] ~]# 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操作
[email protected] : (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 |
+----+-------+-----------+------+---------+-------+----------------------------------+----------------------------------------------------------------------+
[email protected] : (none) 11:14:55> kill 22;
Query OK, 0 rows affected (0.00 sec)

3.2. pstack 工具排查

  • 登錄到MySQL并執行導入b.sql文件操作(不要用strace)
[[email protected] ~]# 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.
[email protected] : (none) 11:08:58> use test
Database changed
[email protected] : test 11:09:00> source /data/mysqldata1/binlog/b.sql;
......
  • 使用pstack工具查看MySQL客戶端連接的進程堆棧信息
# 查看MySQL客戶端連接進程號
[[email protected] ~]# 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工具查看
[[email protected] ~]# 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存儲引擎,喜好專研開源技術,多次在公開場合做過線下線上數據庫專題分享,發表過多篇數據庫相關的研究文章。

我還沒有學會寫個人說明!

女朋友還是游戲?一起來分析下游戲的開發與銷售情況

上一篇

當金融科技遇上云原生,螞蟻金服是怎么做安全架構的?

下一篇

你也可能喜歡

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

長按儲存圖像,分享給朋友

ITPUB 每周精要將以郵件的形式發放至您的郵箱


微信掃一掃

微信掃一掃
重庆时时彩官网直播开奖 小熊猫配资 查看福建22选5走势图 急速赛车计划 江西时时彩5星遗漏 江西11选5走势图一定牛 十一选五开奖结果云南一定牛 宁夏11选5在线购买 全天时时彩领头羊计划 浙江20选5大星彩票网 浙江快乐十二遗漏数据 pc蛋蛋怎样 金融界股票论坛首页 山西快乐10分开奖结果 10分玩法中奖规则 精准二码免费公开 新疆11选五开奖结果一定牛