MySQL中的binlog和redo淺析(r12筆記第5天)

   有一個小問題可能很多人都想起過，那就是MySQL中既然已經有了binlog,為什麼還需要redo,這個問題看起來好像很簡單，但是細細品來，還是有不少值得注意的地方。

    對於資料恢復，尤其是異常當機的情況下，再次啟動的時候，如何恢復，恢復的資料依據，這個尤為重要，在MySQL中是有checkpoint的技術來做一個基本的檢查點控制，也就是常說的LSN,對於事務性資料庫，大都會採用write ahead log的策略，即當前事務提交的時候，先寫redo,在修改相應的頁，如果發生當機導致資料丟失的時候，可以透過重做日誌來完成資料的恢復，但是MySQL和其它有些資料庫有些特別的是這個binlog,它不是採用checkpoint的實現方式，我們可以設想這樣一個情況，一個事務提交的時候，資訊會寫入redo,而在這個操作的過程中，其實binlog的寫入也是同步的，如果redo的資訊在redo log buffer中可能還沒有重新整理到磁碟中，出現當機的情況，就可能導致從庫的資料已經應用了binlog傳輸的資料變化，而redo中還沒來得及提交，這可能就會有資料不一致的情況發生，如果在異常狀態下啟動資料庫就會開啟資料恢復的模式，可能從庫的資料就會出現不一致。

   這種情況聽起來有些特別，但是對於我們理解redo和binlog的問題蠻有幫助，我們來做一個測試吧，僅僅在測試環境中進行除錯所用。

首先為了減少資料的變更影響，我們先做一個flush logs的操作，儘可能保留少，資料變化新的日誌內容

在主庫端切換日誌:
flush logs;

檢視binlog的情況，使用show master status或者show binary logs都可以。
mysql> show master status\G
*************************** 1. row ***************************
             File: binlog.000014
         Position: 230
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 1bb1b861-f776-11e6-be42-782bcb377193:1,
25ee7482-07cd-11e7-a40c-0026b935eb76:1-1502468
1 row in set (0.00 sec)

我們得到mysql服務的程式號。
# ps -ef|grep -w mysqld|grep -v grep|awk '{print $2}'
1751

我們建立一個表test 欄位為id和name(id int ,name varchar(20))

已經存在4條資料如下：

mysql> select *from test.test;
+------+------+
| id   | name |
+------+------+
|    1 | aa   |
|    2 | bb   |
|    3 | cc   |
|    4 | dd   |
+------+------+
4 rows in set (0.00 sec)

從庫 檢視資料和主庫此時是同步的。這是我們測試的一個基礎。

我們可以透過gdb的方式進行簡單除錯。
# gdb -p 1751

就馬上進入了除錯模式，我們可以設定一個斷點。

我們在設定斷點之前先插入2條資料，從庫此時也是5條資料。

mysql> insert into test values(5,'ee');
Query OK, 1 row affected (0.00 sec)

mysql> insert into test values(6,'ff');
Query OK, 1 row affected (0.00 sec)

然後設定斷點，這是關鍵所在。
(gdb) b MYSQL_BIN_LOG::process_commit_stage_queue
Breakpoint 1 at 0xec73ca: file /export/home/pb2/build/sb_0-21378219-1480347226.17/mysql-5.7.17/sql/binlog.cc, line 8430. (2 locations)

然後在主庫嘗試插入一條記錄
insert into test values(7,'gg');
毫無疑問，這條語句會hang住。因為我們的斷點就在提交的時候。

這個時候我們前進一小步，使用c即continue

(gdb) c
Continuing.
[Switching to Thread 0x409c0940 (LWP 1798)]

Breakpoint 1, MYSQL_BIN_LOG::process_commit_stage_queue (this=0x1e8ba00, thd=0xec254e0, first=0xec254e0)
    at /export/home/pb2/build/sb_0-21378219-1480347226.17/mysql-5.7.17/sql/binlog.cc:8430
8430    /export/home/pb2/build/sb_0-21378219-1480347226.17/mysql-5.7.17/sql/binlog.cc: No such file or directory.
        in /export/home/pb2/build/sb_0-21378219-1480347226.17/mysql-5.7.17/sql/binlog.cc
這個時候那條SQL語句依舊是hang的狀態，但是可以看出堆疊，binlog是寫入完成了

從庫此時是應用了資料變更，此時是7條資料。
我們也可以抓取一下binlog,看看裡面是否已經寫入了資料。
[root@grtest s1]# /usr/local/mysql/bin/mysqlbinlog -vv binlog.0000014
可以明顯看到這樣的語句：

...

BINLOG '
DK3KWBPqDAAALgAAAHcDAAAAAOUAAAAAAAEABHRlc3QABHRlc3QAAgMPAhQAAw==
DK3KWB7qDAAAJwAAAJ4DAAAAAOUAAAAAAAEAAgAC//wHAAAAAmdn
'/*!*/;
### INSERT INTO `test`.`test`
### SET
###   @1=7 /* INT meta=0 nullable=1 is_null=0 */
###   @2='gg' /* VARSTRING(20) meta=20 nullable=1 is_null=0 */
# at 926
#170316 23:19:40 server id 3306  end_log_pos 953        Xid = 55
COMMIT/*!*/;
我們此時模擬當機的情況，殺掉程式

 kill -9 1751 29617

然後把binlog改個名字，關閉log_bin
[root@grtest s1]# mv binlog.000014  binlog.000014.bak
再次啟動之後，就會發現此時的主庫中資料還是6條，而從庫卻是7條。
  而如果我們把binlog改回來，開啟log_bin並啟動主庫
mv binlog.000014.bak binlog.000014

   然後再次檢視資料，就會發現主從庫此時的資料竟然不同。從庫的資料明顯要多，這也就從一個側面對映了我們開始的一個設想，在異常當機的情況下，redo的資料還沒有重新整理到redo檔案中，此時已經寫入了binlog,這樣就在這樣一個臨界點導致了主從資料的不一致。

   當然我是使用一個除錯的態度來做的測試，裡面還有很多技巧需要鞏固。