504
技術社區[雲棲]
MySQL · 捉蟲動態 · show binary logs 靈異事件
問題背景
最近在運維 MySQL 中遇到一個神奇的問題，分享給大家。現象是這樣的，show binary logs 沒有返回結果，flush binary logs 後也不行，
但是 binlog 是正常工作的，show master staus 是有輸出的。
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000004
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000004
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
mysql> flush binary logs;
Query OK, 0 rows affected (0.01 sec)
mysql> show binary logs;
Empty set (0.00 sec)
mysql> show master status\G
*************************** 1. row ***************************
File: master-bin.000005
Position: 120
Binlog_Do_DB:
Binlog_Ignore_DB:
Executed_Gtid_Set:
1 row in set (0.00 sec)
mysql>
問題排查
這個問題是筆者第一次遇到，從問題的現象看，binlog 是沒有問題的，可以正常寫入和切換，隻是 show 命令看不到 binlog 文件列表，我們知道 MySQL 是用一個 index 元文件來維護當前使用的 binlog 的，而 show binary logs 也是讀這個文件來展示的，因此問題應該出在 index 文件上。
我們首先檢查 index 文件的權限，發現也是沒問題的，mysqld 進程用戶是有讀寫權限的，然後我們用 tail -f 命令監控 index 文件，另一個窗口連接mysql，執行 flush binary logs，發現新產生的 binlog 文件也是會追加到 index 裏。越排查越覺得詭異，並且沒有排查下去的思路了，難道是 show binary logs 邏輯有問題，翻開代碼確認了下，主體邏輯非常簡單，就是從 index 文件頭開始遍曆，一行對應一個 binlog 文件，每一個 binlog 文件都獲取下文件size，然後把結果發給客戶端，詳見 rpl_master.cc:show_binlogs():
reinit_io_cache(index_file, READ_CACHE, (my_off_t) 0, 0, 0);
/* The file ends with EOF or empty line */
while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)
{
int dir_len;
ulonglong file_length= 0; // Length if open fails
fname[--length] = '\0'; // remove the newline
protocol->prepare_for_resend();
dir_len= dirname_length(fname);
length-= dir_len;
protocol->store(fname + dir_len, length, &my_charset_bin);
if (!(strncmp(fname+dir_len, cur.log_file_name+cur_dir_len, length)))
file_length= cur.pos; /* The active log, use the active position */
else
{
/* this is an old log, open it and find the size */
if ((file= mysql_file_open(key_file_binlog,
fname, O_RDONLY | O_SHARE | O_BINARY,
MYF(0))) >= 0)
{
file_length= (ulonglong) mysql_file_seek(file, 0L, MY_SEEK_END, MYF(0));
mysql_file_close(file, MYF(0));
}
}
protocol->store(file_length);
if (protocol->write())
{
DBUG_PRINT("info", ("stopping dump thread because protocol->write failed at line %d", __LINE__));
goto err;
}
}
代碼邏輯看起來沒毛病，心想這問題真是神奇了。。。筆者都準備掏出 gdb 一步一步跟代碼看了，在此之前抱著試試看的心態，用 vim 打開了 index 文件，準備人肉看一遍，一打開就發現了可疑的地方，文件內容如下：
./master-bin.000001
./master-bin.000002
./master-bin.000003
./master-bin.000004
./master-bin.000005
有沒有看出什麼？
細心的讀者可能已經發現，第一行是空行，再看下剛的代碼，有這麼一個判斷邏輯:
/* The file ends with EOF or empty line */
while ((length=my_b_gets(index_file, fname, sizeof(fname))) > 1)
空行被認為是文件結束，WTF！心中萬頭羊駝奔騰。
解法很簡單，刪了第一行的空行，然後 flush binary logs 生成新的 index 文件把 cache 失效掉，就可以了。
mysql> flush binary logs;
Query OK, 0 rows affected (0.00 sec)
mysql> show binary logs;
+-------------------+-----------+
| Log_name | File_size |
+-------------------+-----------+
| master-bin.000001 | 467 |
| master-bin.000002 | 168 |
| master-bin.000003 | 168 |
| master-bin.000004 | 168 |
| master-bin.000005 | 168 |
| master-bin.000006 | 120 |
+-------------------+-----------+
6 rows in set (0.00 sec)
那麼下一個問題來了，為什麼第一行會是個空行呢，因為之前主機磁盤被堆滿，為了快速清出空間，運維同學把一些老的 binlog 清理掉了，同時 “貼心的” 的把 index 文件也同步手動編輯了，但是因為手殘留下了一個空行。。。
問題總結
這個問題是比較簡單的，遇到過一次的話，後麵就不會被坑了。。。
從這個問題我們也可以看出，MySQL 在有些時候的邏輯處理非常粗糙簡單，對於文件格式沒有適當地檢測機製，像這種詭異問題就被隱藏吞沒掉。如果翻看 commit 曆史的話，可以看到“空行就認為是文件結束”的邏輯，在2002年之後就一直是這樣的了:-(
最後更新：2017-09-21 09:03:28