故障分析 | binlog flush 失敗導致的 Crash

• 2020 年 3 月 13 日
• 筆記

一、問題現象

某項目上出現 MySQL Crash，相關 errorlog 日誌如下，從日誌可以看出是 binlog error 導致的問題，但是無法確認具體原因，網上大部分資料都說是由於空間已滿導致，後來在系統日誌( /var/log/message)中確實找到了 / 分區空間已滿的信息，所以基本可以確認 binlog error 是由於磁盤空間已滿導致，進而造成 MySQL Crash。

2019-09-24T14:17:47.786460+08:00 527621 [ERROR] /usr/local/mysql/bin/mysqld: Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Hence aborting the server.  06:17:47 UTC - mysqld got signal 6 ;  This could be because you hit a bug. It is also possible that this binary  or one of the libraries it was linked against is corrupt, improperly built,  or misconfigured. This error can also be caused by malfunctioning hardware.  Attempting to collect some information that could help diagnose the problem.  As this is a crash and something is definitely wrong, the information  collection process might fail.    key_buffer_size=8388608  read_buffer_size=16777216  max_used_connections=79  max_threads=2500  thread_count=35  connection_count=34  It is possible that mysqld could use up to  key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 122921649 K  bytes of memory  Hope that's ok; if not, decrease some variables in the equation.    Thread pointer: 0x7fbc3400ef40  Attempting backtrace. You can use the following information to find out  where mysqld died. If you see no messages after this, something went  terribly wrong...  stack_bottom = 7fbcd01d9ea8 thread_stack 0x40000  /usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xf4fbe5]  /usr/local/mysql/bin/mysqld(handle_fatal_signal+0x4a4)[0x7d1f54]  /lib64/libpthread.so.0(+0xf370)[0x7fc5897fe370]  /lib64/libc.so.6(gsignal+0x37)[0x7fc5881f21d7]  /lib64/libc.so.6(abort+0x148)[0x7fc5881f38c8]  /usr/local/mysql/bin/mysqld[0xee626a]  /usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG33handle_binlog_flush_or_sync_errorEP3THDb+0x17b)[0xef289b]  /usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG14ordered_commitEP3THDbb+0x3ca)[0xef480a]  /usr/local/mysql/bin/mysqld(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0x51d)[0xef4f7d]  /usr/local/mysql/bin/mysqld(_Z15ha_commit_transP3THDbb+0x174)[0x823434]  /usr/local/mysql/bin/mysqld(_Z12trans_commitP3THD+0x49)[0xdd38f9]  /usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x2c89)[0xd1a1a9]  /usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x40d)[0xd1c86d]  /usr/local/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x11a5)[0xd1da95]  /usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0x194)[0xd1e944]  /usr/local/mysql/bin/mysqld(handle_connection+0x2b4)[0xdeffa4]  /usr/local/mysql/bin/mysqld(pfs_spawn_thread+0x174)[0xfc8f64]  /lib64/libpthread.so.0(+0x7dc5)[0x7f097d411dc5]  /lib64/libc.so.6(clone+0x6d)[0x7f097becf73d]    Trying to get some variables.  Some pointers may be invalid and cause the dump to abort.  Query (7f00a80008f0): is an invalid pointer  Connection ID (thread ID): 98525  Status: NOT_KILLED

二、問題疑惑

對於這個問題，一開始存在幾點疑惑，需要實驗和源碼追蹤驗證。

1. binlog error 是由於 / 分區空間已滿造成的，為什麼會造成 MySQL Crash？

2. / 分區明明有十幾個 G 的剩餘空間，為什麼會滿？是什麼文件撐滿的？為啥事後空間卻自動釋放了？

這裡就已知的知識先猜測下問題過程，是否正確則需要測試驗證，內部機制可能就需要去查看源碼。

大概過程如上，項目上 /tmp 默認為 MySQL 的臨時文件目錄，其所在分區一般為 / 分區(根分區)，而 MySQL 的數據目錄都存放在 /data/mysql_data 為另一個單獨的分區( /data 分區)，項目上一般均是如此。

#bin包默認值  datadir = /data/mysql_data  tmpdir = /tmp

當 /tmp 空間不足，也就是 /分區 已滿的情況下，導致 binlog flush 無法進行下去，拋出 binlog_error 的異常，導致 MySQL crash！

三、資料查閱

針對這個問題，網上進行大量資料查閱後，相關知識點總結如下：

與此次問題相關最主要的 2 個 MySQL 參數。

#bin包默認值  binlog_cache_size=32768  binlog_error_action = ABORT_SERVER

binlog_cache_size：當事務開始時，MySQL 會分配一個 binlog_cache_size 大小的緩衝區（默認 32K）給 session 用於存儲二進制日誌的緩存。如果事務大於 binlog_cache_size（默認 32K），線程將打開一個 臨時文件 用於存儲事務(默認 /tmp 下）， 當線程結束時，臨時文件會自動被刪除。

binlog_error_action：默認值為 ABORT_SERVER，會使 MySQL 在寫 binlog 遇到嚴重錯誤時直接退出( 即 Crash 動作)，比如磁盤滿了，文件系統不可寫入等。在 ABORT_SERVER 選項下，binlog 和從庫都是安全的，這是官方選擇此默認值的原因。

此時我們就已經可以回答之前提的問題了~

1. binlog error 是由於 / 分區空間已滿造成的，為什麼會造成 MySQL Crash？

• 因為 binlog_error_action 參數默認值為 ABORT_SERVER，在 binlog 寫入錯誤時會選擇直接退出保證 binlog 安全。

2. / 分區明明有十幾個 G 的剩餘空間，為什麼會滿？是什麼文件撐滿的？為啥事後空間卻自動釋放了？

• 猜測是由於事務較大，超過了 binlog_cache_size，所以會在 /tmp(即 / 分區) 下生成臨時文件，導致 / 分區空間不足，引起 MySQL Crash 後，空間又自動釋放，所以事後看 / 分區空間是正常的。

四、測試模擬

本地環境（為方便測試，與上述分區略有不同）：

Filesystem           Size  Used Avail Use% Mounted on  /dev/mapper/cl-root   96G   57G   39G  60% /               <-------- datadir = /data/mysql_data  /dev/mapper/cl-tmp   3.8G   33M  3.8G   1% /data/tmp       <-------- tmpdir  = /data/tmp

模擬 多條 SQL 組成的超大事務，在存儲過程中顯示開啟事務， 循環插入 1kw 數據，觀察 tmpdir 目錄使用情況。

直接在 /data/tmp 下無法看到臨時文件，只有通過 lsof 命令才可以看到在 tmpdir 目錄下確實生成了臨時文件，且一直在增長，佔用了 tmpdir 目錄下的大量空間。

存儲過程最終執行報錯，報 Nospace left on device 即臨時目錄空間不足，但是此時 MySQL 並沒有 Crash，errorlog 里未出現報錯！！！

經過測試驗證，當報錯的時候，如果你在 同一個會話下 執行 commit 或者 再開啟一個事務 就會立即觸發 binlog_error_action，導致 MySQL 立即崩掉，且 errorlog 里會出現 binlog error 報錯，與項目上現象一致。

PS：當 MySQL 解釋器遇到 start transaction 時候會觸發 commit… !!!

mysql> call test_insert();  ERROR 1026 (HY000): Error writing file '/data/tmp/ML1aShmH' (errno: 28 - No space left on device)  mysql> commit;  ERROR 1598 (HY000): Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Hence aborting the server.

mysql> call test_insert();  ERROR 1026 (HY000): Error writing file '/data/tmp/ML5b0Mj6' (errno: 28 - No space left on device)  mysql> start transaction;  ERROR 1598 (HY000): Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Hence aborting the server.

五、源碼跟蹤

跟蹤 MySQL 源碼驗證上述猜想及測試，不感興趣的童鞋可以直接跳過~

為了查看上述測試過程到底是在源碼的哪一步最先報了錯誤，所以對比了 2 份 DBUG 日誌， 左圖 是 報錯 的跟蹤日誌， 右圖 為 不報錯 的跟蹤日誌。

可以看到報錯的跟蹤日誌最終是在 my_write 函數 中拋出錯誤，而不報錯的日誌則正常執行完 my_write 函數。

//Write a chunk of bytes to a file  size_t my_write(File Filedes, const uchar *Buffer, size_t Count, myf MyFlags)  {      size_t writtenbytes;      size_t sum_written= 0;      const size_t initial_count= Count;        for (;;)      {          //...          #ifdef _WIN32              writtenbytes= my_win_write(Filedes, Buffer, Count);          #else              writtenbytes= write(Filedes, Buffer, Count); //writtenbytes為實際寫入的位元組數          //...          if (writtenbytes == Count)  //判斷實際寫入的位元組數與要求寫入的位元組數是否相符          {            //寫入正常則直接break跳出循環,正常結束.            sum_written+= writtenbytes;            break;          }          //...      }      //...      if (MyFlags & (MY_NABP | MY_FNABP))      {          if (sum_written == initial_count)  //寫入正常走這個邏輯，返回0代表成功            DBUG_RETURN(0);          if (MyFlags & (MY_WME | MY_FAE | MY_FNABP)) //寫入過程報錯走這個邏輯          {            char errbuf[MYSYS_STRERROR_SIZE];            my_error(EE_WRITE, MYF(0), my_filename(Filedes),                 my_errno(), my_strerror(errbuf, sizeof(errbuf), my_errno())); //打印錯誤信息          }          DBUG_RETURN(MY_FILE_ERROR); //返回錯誤      }      //...  }    /*  源碼如上,MySQL最終會走Linux內核方法write(Filedes, Buffer, Count)來刷新binlog緩衝至磁盤文件中。  1.Filedes為文件號（對應/proc/mysqld_pid/fd下的文件編號）  2.Buffer為指向所需寫入緩衝的指針。  3.Count為所需要寫入的位元組數。    my: fd: 51  Buffer: 0x7f24c49e9e30  Count: 27    由於/data/tmp磁盤已滿，無法寫入Count所需的位元組數，導致writtenbytes!=Count，然後引起了後續一系列的代碼報錯，最終誘發binlog_error_action->MySQL Crash.  */

MySQL 源碼執行 Commit 報錯過程精簡如下：

T@12: | >trans_commit  T@12: | | >ha_commit_trans  T@12: | | | >MYSQL_BIN_LOG::commit  T@12: | | | | >MYSQL_BIN_LOG::ordered_commit  T@12: | | | | | >MYSQL_BIN_LOG::process_flush_stage_queue  T@12: | | | | | | >binlog_cache_data::flush  T@12: | | | | | | | >MYSQL_BIN_LOG::write_cache(THD *, binlog_cache_data *, bool)  T@12: | | | | | | | | >MYSQL_BIN_LOG::do_write_cache  T@12: | | | | | | | | | >reinit_io_cache  T@12: | | | | | | | | | | >my_b_flush_io_cache  T@12: | | | | | | | | | | | >my_write  T@12: | | | | | | | | | | | | my: fd: 52Buffer: 0x7f9ccc050db0Count: 27MyFlags: 20  T@12: | | | | | | | | | | | | error: Write only -1 bytes, error: 28  T@12: | | | | | | | | | | | | >my_error  T@12: | | | | | | | | | | | | | >my_message_sql  T@12: | | | | | | | | | | | | | | error: error: 3  message: 'Error writing file '/data/tmp/MLJRp8sa' (Errcode: 28 - No space left on device)'  T@12: | | | | | | | | | | | | | <my_message_sql 2281  T@12: | | | | | | | | | | | | <my_error 211  T@12: | | | | | | | | | | | <my_write 122  T@12: | | | | | | | | | | <my_b_flush_io_cache 1583  T@12: | | | | | | | | | <reinit_io_cache 367  T@12: | | | | | | | | <MYSQL_BIN_LOG::do_write_cache 7679  T@12: | | | | | | | <MYSQL_BIN_LOG::write_cache(THD *, binlog_cache_data *, bool) 8031  T@12: | | | | | | <binlog_cache_data::flush 1740  T@12: | | | | | <MYSQL_BIN_LOG::process_flush_stage_queue 8848  T@12: | | | | | >my_error  T@12: | | | | | | >my_message_sql  T@12: | | | | | | | error: error: 1598  message: 'Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Hence aborting the server.'  T@12: | | | | | | | >sql_print_error  T@12: | | | | | | | | >error_log_print  T@12: | | | | | | | | | >print_buffer_to_file  T@12: | | | | | | | | | | enter: buffer: /opt/mysql-5.7.24-linux-glibc2.12-x86_64/bin/mysqld-debug: Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action'isset to 'ABORT_SERVER'. Hence aborting the server.  2019-11-11T11:54:45.434783+08:0012[ERROR] /opt/mysql-5.7.24-linux-glibc2.12-x86_64/bin/mysqld-debug: Binary logging not possible. Message: An error occurred during flush stage of the commit. 'binlog_error_action'isset to 'ABORT_SERVER'. Hence aborting the server.  T@12: | | | | | | | | | <print_buffer_to_file 2109  T@12: | | | | | | | | <error_log_print 2134  T@12: | | | | | | | <sql_print_error 2148  T@12: | | | | | | <my_message_sql 2281  T@12: | | | | | <my_error 211

六、擴展內容

下圖這個報錯其實就是本次問題的一個日常例子，很多童鞋通過 navicate 還原 MySQL 的時候可能就會碰到這個問題，本質就是 navicate 還原數據庫的時候默認會走 事務，當表數據庫較大時，事務大小超過 binlog_cache_size，就會用臨時表記錄事務數據，當 tmdir 目錄磁盤不足就會報錯，但是這種情況並不會造成 MySQL Crash，因為 navicate 在還原報錯後並不會繼續去執行commit 或 另開一個事務，而是直接斷開連接。

七、總結

這個問題目前在項目上很少碰到，這次也是出於好奇拿來學習探討，下面總結下這個問題出現的場景：

1. 代碼中存在較大事務，超過 binlog_cache_size，高並發下生成大量臨時文件，佔滿 tmpdir。

2. 代碼在事務執行過程中碰到 tmpdir 磁盤已滿錯誤，未處理異常執行回滾，後續執行 Commit 導致。

3. 代碼在事務執行過程中碰到 tmpdir 磁盤已滿錯誤，未處理異常執行回滾，繼續執行碰到嵌套事務，引發 Commit 導致。

也許很多童鞋想到可以 加大binlog_cache_size 來減少臨時文件的產生，但是這樣會增加內存消耗，試想以下，假如 binlog_cache_size 增加到 32MB，當有 300 個數據庫連接 時，每個連接都會分配 32MB 的 binlog_cache( 不管你用多少)，那麼就是將近 10G，很容易導致內存溢出，被系統 OOM。

因此 binlog_cache_size 不可能增加很多，根本解決方法是減少事務大小，避免在高並發下同時產生大量臨時文件，撐滿 tmpdir；另外可以增加 tmpdir 所在分區的大小。

遺留問題：

CentOS Linux release 7.3.1611 問題復現成功，commit 會導致 Crash。

CentOS Linux release 7.6.1810 問題無法復現，commit 不報錯，但是會造成 binlog event 部分寫。

附錄： https://blog.51cto.com/lee90/1939469 https://dev.mysql.com/doc/refman/5.7/en/replication-options-binary-log.html https://stackoverflow.com/questions/37813819/mysql-max-binlog-cache-size-vs-binlog-cache-size