BUG解析:InnoDB兩次寫與多實例buffer pool
在我測試過程中，使用的是自動提交，一條語句為一個事務，開8個線程的話大概是單線程復制的5倍（共有20個表），性能應該還是不錯的，多線程下QPS可以達到32000，單線程差不多6500，但是這是把double write關了的情況，如果打開了double write，那么一開始的QPS也差不多是32000，但做幾分鐘之后，這個數字一直在減小，那個感覺啊真是不好，怎么老是一直減少呢，等到跟上來了，一直看著它減少到15000，這個很不好，相當于是2倍的提升，這個看上去完全是因為double write的影響，因為只是修改了這么一個參數而出現的兩個不同的結果，但是查遍了網上也都說double write的影響只會是5-10%，那么就奇怪了，我這個的影響明顯是50%以上啊，難道是兩次寫就是50%？不對的，因為double write本來就是連續寫的。肯定是哪里有其它的問題。
然后在無奈之下，在測試時，通過pstack工具看MYSQL運行時慢到底是什么樣的堆棧，到底是在等啥？什么影響了它的性能，然后看到很多時候堆棧都是這樣的：
- Thread 4 (Thread 0x7fdadd357700 (LWP 9800)):
- #1 0x00000000008d3007 in os_event_wait_low ()
- #2 0x00000000008230ae in sync_array_wait_event ()
- #3 0x0000000000823f46 in mutex_spin_wait ()
- #4 0x00000000008674df in buf_flush_buffered_writes ()
- #5 0x0000000000868b97 in buf_flush_batch ()
- #6 0x000000000086a6df in buf_flush_list ()
- #7 0x00000000008c31b2 in log_check_margins ()
- #8 0x00000000008eba6a in row_ins_index_entry_low ()
- #9 0x00000000008efd9e in row_ins_step ()
- #10 0x0000000000803be9 in row_insert_for_mysql ()
- #11 0x00000000007f2d6c in ha_innobase::write_row(unsigned char*) ()
- #12 0x000000000068c760 in handler::ha_write_row(unsigned char*) ()
- #13 0x000000000055a2ed in write_record(THD*, TABLE*, st_copy_info*) ()
- Thread 3 (Thread 0x7fdadd316700 (LWP 9801)):
- #1 0x00000000008d3007 in os_event_wait_low ()
- #2 0x00000000008230ae in sync_array_wait_event ()
- #3 0x0000000000823f46 in mutex_spin_wait ()
- #4 0x00000000008674df in buf_flush_buffered_writes ()
- #5 0x0000000000868b97 in buf_flush_batch ()
- #6 0x000000000086a6df in buf_flush_list ()
- #7 0x00000000008c31b2 in log_check_margins ()
- #8 0x00000000008eba6a in row_ins_index_entry_low ()
- #9 0x00000000008efd9e in row_ins_step ()
- #10 0x0000000000803be9 in row_insert_for_mysql ()
- #11 0x00000000007f2d6c in ha_innobase::write_row(unsigned char*) ()
- #12 0x000000000068c760 in handler::ha_write_row(unsigned char*) ()
- #13 0x000000000055a2ed in write_record(THD*, TABLE*, st_copy_info*) ()
從上面的堆棧中可以看出，SQL線程很多都是在buf_flush_buffered_writes函數中等待，而這個函數正好是處理double write的函數，所以我重點看了這里，然后一進去就明白了是為什么了，看到這個函數一開始有一行mutex_enter(&(trx_doublewrite->mutex))，而在函數退出前有一行mutex_exit(&(trx_doublewrite->mutex))，里面是處理所有double write緩存起來的頁面，也就是前面要刷的頁面，因為INNODB支持多個BUFFER POOL實例，這樣可以增大并發度，頁面可以放在不同的BUFFER POOL中，這樣兩個BUFFER POOL中的頁面在同時訪問時可以互不干擾，那么可想而知，double write緩存的頁面就是來自多個SQL線程并發收集起來的，那么很容易想到，問題其實就里在這里，由多個線程做檢查點，但只有一個線程會做double write，這樣產生了瓶頸，導致等待一段時間后就會越來越慢，也許就是這個問題，那后面就看了一下代碼，它的實現是否允許多個線程做檢查點呢，主要是看函數log_free_check（log_check_margins）的實現，因為這個函數才是用戶線程調用的，代碼是這樣的：
- log_free_check(void)
- {
- if (log_sys->check_flush_or_checkpoint)
- log_check_margins();
- }
那就主要是log_sys->check_flush_or_checkpoint有沒有可能多個線程進來了，最后發現在里面直接就調log_checkpoint_margin函數了，而再進去里面，就是對buffer pool中的臟頁面進行刷盤了，同時這里刷盤是刷每一個buffer pool instance的，而不是分開自己刷自己的，當然對于某一個buffer pool instance，只會有一個線程做，進來之后會找到沒有任何一個線程在做刷盤的buffer pool instance來做，所以其實是并發處理這多個buffer pool instance的，那么現在得到的結論就是經常性的多個線程一起做刷盤操作，而做完刷盤之后，如果打開了double write，則要將所有的buffer pool instance要刷的頁面做double write，上面也看到了，它是一個mutex，多個線程一起搶這一個臨界區，導致系統的并發度大大的降低，那么現在問題已經很明顯，原因也已經很明顯，這個其實與DOUBLEWRITE沒關系，那個5-10%我還是承認的，這里只不過是代碼實現有問題而已。
那么結論就里說，這其實是INNODB的一個BUG，就是多BUFFERPOOL實例下，DOUBLEWRITE會導致系統并發性能大大降低的問題。
那如何解決呢？
首先我已經向bugs.mysql.com報了BUG，鏈接http://bugs.mysql.com/bug.php?id=67808&edit=2，本人英語不好，寫得挺費勁。
難道就這樣等它解決嗎？不對，我已經等不上了，即使出來了也不是在5.5.27上啊，所以自己解決吧。
這里歸根結底的問題就是做檢查點函數log_checkpoint_margin中存在并發，導致DOUBLEWRITE的瓶頸出現了，因為在INNODB的增刪改操作的一開始，都會直接先調用log_free_check這個函數，出現這樣的問題的概率太高了。
想想，這個做檢查點需要多個線程嗎？如果是一個線程在做是不是就沒有問題了？DOUBLEWRITE的瓶頸也不存在了？確實是這樣的。
再想想，做檢查點需要多個線程嗎？只有一個線程做是不是就夠了？因為檢查點歸根結底是為了給日志讓空間出來，日志一直往2個（默認）日志文件中循環添加，第一個寫完寫第二個，寫完第二個再寫第一個，其實就里一個圈，不斷的循環，那么這里就必須要保證，向里面寫的數據的位置不能走到檢查點的位置的前面去（因為數據的LSN是新產生的日志的LSN，肯定是要小于檢查點的LSN的，也可以表示為，數據的LSN必須要小于檢查點的LSN加上整個日志組的日志容量），因為檢查點LSN前面的日志表明，所有數據已經都寫入磁盤了，可以扔掉了，那如果大于了，就會把沒有做檢查點的日志覆蓋掉，這樣會導致數據錯誤或者更嚴重的一些問題。
有了這樣的想法，則這個問題應該不難解決，先在log_sys中加入一個成員checkpoint_doing，用來表示現在是否有線程正在做檢查點，再修改函數log_check_margins，最前面加上代碼段：
- mutex_enter(&(log_sys->mutex));
- if (log_sys->checkpoint_doing > 0) {
- mutex_exit(&(log_sys->mutex));
- return;
- }
- log_sys->checkpoint_doing++;
- mutex_exit(&(log_sys->mutex));
上面這表示如果有線程已經做了，那這里不會再進去，直接就出去了，如果沒有線程在做，那么當前線程才做，同時將標志置為正在做。這樣保證了只有一個用戶線程會做檢查點。當然在修改及判斷這個checkpoint_doing的時候必須要對其進行保護，上面代碼中也已經有所體現。那么這樣就好了嗎？如果當前系統的壓力非常大，那么出去了，而沒有做檢查點檢查，繼續做寫操作，這樣有可能會導致新的日志寫的超過了檢查點的位置，導致數據覆蓋，所以還需要做一個修改操作。
因為在INNODB中寫日志的函數只有log_write_up_to，并且這只會有一個線程寫，那么為了防止這個問題的話是不是在它寫日志的時候檢查一下，如果空間不夠了等待或者做一次檢查點后再繼續做，是不是就沒有問題了？我認為確實是這樣的，那么繼續修改：
- if (!log_sys->checkpoint_waiting && log_sys->lsn - log_sys->last_checkpoint_lsn > log_sys->max_checkpoint_age)
- {
- mutex_exit(&(log_sys->mutex));
- log_sys->checkpoint_waiting = 1;
- log_check_margins();
- log_sys->checkpoint_waiting = 0;
- goto loop;
- }
這段代碼就加在log_write_up_to函數中五個判斷條件之后，能走到這里說明這次的日志要寫入日志文件了，那么這里檢查是最合適的，上面的代碼有一個條件判斷，最主要是的log_sys->lsn - log_sys->last_checkpoint_lsn > log_sys->max_checkpoint_age，這個表示的是如果當前的最新LSN超過檢查點LSN的數目已經大于最大的做檢查點差值數，則就等待或者做一次檢查點，這個條件與log_checkpoint_margin函數中判斷是不是要做檢查點的條件是一樣的，這樣的話就保證了這段代碼中調用了log_check_margins時要么里面已經有人正在做，要么自己肯定能做一次檢查點，不然在這里會產生死循環。做了之后從而使的log_sys->last_checkpoint_lsn變大，向前走，讓出空間，這樣這次日志就可以寫入進去了，那么goto loop可以起到循環等待的作用。
上面還看到一個新的成員checkpoint_waiting，這個是為了防止進入死循環而設置的，因為log_check_margins里面還會再調用log_write_up_to。
那么到現在為止，這個問題應該算是可以了的，接下來就是測試了，把多線程的SLAVE復制跑起來，我發現這個是一個非常好的并發測試工具，不需要專門寫應用來設置并發環境。
測試的結果表明，那么問題不復存在，平均的QPS在打開DOUBLEWRITE時都是31000，這個數字挺好的。問題解決，同時發現那個分支就從來沒有進去過，說明用戶線程做了已經足夠了，那里只是一個機率很小的問題預防而已。
但是這個修改現在還沒有辦法去驗證，只能由各位先從理論上看看是不是正確吧，我本人認為應該還是沒什么大問題的，請各位大俠指點！
這里要感謝一下我的好朋友好戰友陳福榮同學，在MYSQL學習及實現方面一直不斷的討論，研究，我們共同進步。
原文鏈接：http://www.cnblogs.com/bamboos/archive/2012/12/05/2802997.html
【編輯推薦】
- 適合初學者的MySQL學習筆記之庫操作示例
- 適合初學者的MySQL學習筆記之表操作示例
- 適合初學者的MySQL學習筆記之MySQL管理心得
- 適合初學者的MySQL學習筆記之MySQL查詢示例
- 適合初學者的MySQL學習筆記之管理員常用操作總結
