背景：最近在做一台線上服務器IO負載情況的時候發現了以下現象：
24小時的IO_UTIL 的曲線看似風平浪靜，毛刺較少
但當圖片放大到半小時級別的時候發現IO_UTIL即磁盤使用率出現了規律性的波動，見下圖：
本文就將從這個現象觸發，探究出現這樣規律性波動的原因。
Step1： 服務器上進行實時IO負載查看
通過iostat -x 1 每隔一秒對IO使用情況進行一次負載查看。可以看到UTIL有規律性的波動（10秒1次）。
且負載的主要來源在於寫請求（負載高時，wsec/s 也同步升高）
又由於服務器是MySQL獨占，所以比較容易的就可以將原因歸結為是MySQL的數據刷寫導致（log/data)。
看到這里大神們應該已經不難猜到是MySQL內部 src_master_thread 中10_seconds 循環搗的鬼了。
為了保證診斷思路的連貫性，接下來還是把當時的操作復述一遍。
root@db-mysql-tg03b.nh:/root>iostat -x 1 vgca0 |grep vgca0
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util vgca0 0.00 0.00 12.96 371.75 1562.56 24314.49 67.26 0.37 0.28 0.28 10.62 vgca0 0.00 0.00 2.00 2.00 40.00 138.00 44.50 0.00 1.00 1.00 0.40 vgca0 0.00 0.00 1.00 2.00 32.00 170.00 67.33 0.00 1.00 1.00 0.30 vgca0 0.00 0.00 3.00 2.00 96.00 130.00 45.20 0.00 0.80 0.80 0.40 vgca0 0.00 0.00 4.00 2.00 128.00 178.00 51.00 0.00 0.67 0.67 0.40 vgca0 0.00 0.00 1.00 5.00 32.00 170.00 33.67 0.00 0.83 0.83 0.50 vgca0 0.00 0.00 0.00 1868.00 0.00 101510.00 54.34 1.28 0.16 0.16 30.20 vgca0 0.00 0.00 7.00 2.00 200.00 130.00 36.67 0.10 12.78 12.78 11.50 vgca0 0.00 0.00 1.98 1.98 39.60 160.40 50.50 0.00 1.00 1.00 0.40 vgca0 0.00 0.00 6.00 2.00 168.00 170.00 42.25 0.00 0.88 0.88 0.70 vgca0 0.00 0.00 4.00 26.00 104.00 5026.00 171.00 0.02 0.73 0.73 2.20 vgca0 0.00 0.00 10.00 2.00 296.00 164.00 38.33 0.04 3.92 3.92 4.70 vgca0 0.00 0.00 1.00 2.00 8.00 138.00 48.67 0.00 1.00 1.00 0.30 vgca0 0.00 0.00 2.00 2.00 40.00 162.00 50.50 0.00 1.00 1.00 0.40 vgca0 0.00 0.00 3.00 2.00 72.00 170.00 48.40 0.00 0.80 0.80 0.40 vgca0 0.00 0.00 2.00 6.00 40.00 172.00 26.50 0.00 0.50 0.50 0.40 vgca0 0.00 0.00 2.00 601.00 40.00 32942.00 54.70 0.39 0.17 0.17 10.40 vgca0 0.00 0.00 2.00 1179.00 16.00 63932.00 54.15 0.82 0.17 0.17 19.90 vgca0 0.00 0.00 3.96 1.98 126.73 144.55 45.67 0.00 1.50 1.50 0.89 vgca0 0.00 0.00 3.00 2.00 96.00 170.00 53.20 0.00 1.00 1.00 0.50 vgca0 0.00 0.00 4.00 3.00 104.00 162.00 38.00 0.00 0.86 0.86 0.60 vgca0 0.00 0.00 1.00 2.00 8.00 138.00 48.67 0.00 0.33 0.33 0.10 vgca0 0.00 0.00 6.00 2.00 168.00 178.00 43.25 0.00 1.12 1.12 0.90 vgca0 0.00 0.00 5.00 2.00 136.00 138.00 39.14 0.00 0.86 0.86 0.60 vgca0 0.00 0.00 4.00 2.00 104.00 170.00 45.67 0.00 0.83 0.83 0.50 vgca0 0.00 0.00 2.00 2.00 40.00 162.00 50.50 0.00 1.00 1.00 0.40 vgca0 0.00 0.00 1.00 5.00 8.00 187.00 32.50 0.00 0.50 0.50 0.30 vgca0 0.00 0.00 7.00 1815.00 104.00 98762.00 54.26 1.31 0.25 0.25 45.50 vgca0 0.00 0.00 5.00 2.00 136.00 178.00 44.86 0.00 0.86 0.86 0.60
Step2： 確定MySQL write IO 來源
由於目前只知道是MySQL數據刷寫導致，那么究竟是redo-log還是data page flush造成的現在還不知道。
innodb內部關於write的statistics還是比較有限的。因此比較粗暴的寫了個類似於top的perl腳本 ，監控這些參數。
腳本如下，有興趣的同學可以展開閱讀
use strict; use warnings; use utf8; use DBI; my $CONFIG_SERVER_IP ='127.0.0.1'; my $CONFIG_SERVER_DB='test'; my $CONFIG_SERVER_PORT='3306'; my $CONFIG_SERVER_USER='user'; my $CONFIG_SERVER_PASS='password'; my $conf_dbh = DBI->connect("DBI:mysql:$CONFIG_SERVER_DB;host=$CONFIG_SERVER_IP;port=$CONFIG_SERVER_PORT", $CONFIG_SERVER_USER, $CONFIG_SERVER_PASS,{RaiseError => 1}) || die "Could not connect to database: $DBI::errstr"; my %last_value_hash; print "data_write\tdata_written\tdblwr_pages_written\tdblwr_writes\tlog_write_req\tos_log_fsync\tos_log_written\tpages_written\n"; while(1){ my $conf_sth = $conf_dbh->prepare("show global status like '%innodb%'") || die "Prepare error"; $conf_sth->execute(); while(my $row=$conf_sth->fetchrow_hashref){ my $name=$row->{Variable_name}; my $value=$row->{Value}; if( $name eq 'Innodb_data_writes' || $name eq 'Innodb_data_written' || $name eq 'Innodb_dblwr_pages_written' || $name eq 'Innodb_dblwr_writes' || $name eq 'Innodb_log_write_requests' || $name eq 'Innodb_os_log_fsyncs' || $name eq 'Innodb_os_log_written' || $name eq 'Innodb_pages_written'){ $last_value_hash{$name}=0 if( !defined($last_value_hash{$name}) ); my $value_step=$value-$last_value_hash{$name}; $last_value_hash{$name}=$value; print "$value_step\t"; } } print "\n"; sleep 1; }
最后得到參數的波動情況如下：
可以看到 innodb_data_writes / innodb_data_written / innodb_dblwr_pages_written / innodb_pages_written 都有和IO_UTIL一樣有10秒一次的波動。
再結合上iostat中 wsec/s 較大的數值，基本可以確定IO高負載的元凶是data page的flush，而不是redo log的flush
data_write data_written dblwr_pages_written dblwr_writes log_write_req os_log_fsync os_log_written pages_written 1 79360 0 0 169 1 79360 0 1 72192 0 0 127 1 72192 0 1 67072 0 0 139 1 67072 0 1 69120 0 0 149 1 69120 0 1 74752 0 0 128 1 74752 0 1 61952 0 0 134 1 61952 0 1 71168 0 0 131 1 71168 0 1 62976 0 0 126 1 62976 0 1 71168 0 0 109 1 71168 0 1388 44870144 1367 14 125 6 75776 1367 1 66048 0 0 158 1 66048 0 1 73728 0 0 144 1 73728 0 1 69632 0 0 126 1 69632 0 1 75776 0 0 172 1 75776 0 1 88576 0 0 151 1 88576 0 1 67584 0 0 134 1 67584 0 1 80384 0 0 155 1 80384 0 1 86528 0 0 191 1 86528 0 1 72704 0 0 135 1 72704 0 1525 49385984 1504 13 154 5 102400 1504 1 74752 0 0 158 1 74752 0
Step3 ： Innodb 什么時候做dirty data page的flush
由於之前對於innodb的數據刷寫也只是略知一二，網上對於刷寫策略也是眾說紛紜，診斷到了這里貌似就無法深入了。
其實真相就靜靜的躺在那里：源代碼閱讀。
Innodb寫磁盤的代碼路徑非常清晰，比較容易閱讀。主要代碼在 storage/innodb_plugin/Buf/Buf0flu.c 中
代碼比較冗長這里就不貼了，主要敘述下大致的調用關系。
buf_flush_batch 調用 buf_flush_try_neighbors （嘗試刷寫neighbor page）
buf_flush_try_neighbors 調用 buf_flush_page （刷寫單個page）
buf_flush_page調用buf_flush_write_block_low （實際刷寫單個page）
buf_flush_write_block_low調用buf_flush_post_to_doublewrite_buf （將page放到double write buffer中，並准備刷寫）
buf_flush_post_to_doublewrite_buf 調用 fil_io （ 文件IO的封裝）
fil_io 調用 os_aio （aio相關操作）
os_aio 調用 os_file_write （實際寫文件操作）
其中buf_flush_batch 只有兩種刷寫方式： BUF_FLUSH_LIST 和 BUF_FLUSH_LRU 兩種方式的方式和觸發時機簡介如下：
BUF_FLUSH_LIST: innodb master線程中 1_second / 10 second 循環中都會調用。觸發條件較多（下文會分析）
BUF_FLUSH_LRU: 當Buffer Pool無空閑page且old list中沒有足夠的clean page時，調用。刷寫臟頁后可以空出一定的free page，供BP使用。
從觸發頻率可以看到 10 second 循環中對於 buf_flush_batch( BUF_FLUSH_LIST ) 的調用是10秒一次IO高負載的元凶所在。
我們再來看10秒循環中flush的邏輯：
通過比較過去10秒的IO次數和常量的大小，以及pending的IO次數，來判斷IO是否空閑，如果空閑則buf_flush_batch( BUF_FLUSH_LIST,PCT_IO(100) );
如果臟頁比例超過70，則 buf_flush_batch( BUF_FLUSH_LIST,PCT_IO(100) );
否則 buf_flush_batch( BUF_FLUSH_LIST,PCT_IO(10) );
可以看到由於SSD對於隨機寫的請求響應速度非常快，導致IO幾乎沒有堆積。也就讓innodb誤認為IO空閑，並決定全力刷寫。
其中PCT_IO(N) = innodb_io_capacity *N% ，單位是頁。因此也就意味着每10秒，innodb都至少刷10000個page或者刷完當前所有臟頁。
updated on 2013/10/31: 在5.6中官方的adaptive flush算法有所改變，但是空閑狀態下innodb_io_capacity對於刷寫page數量的影響仍然不改變。
具體見：文章鏈接
Step4： 進一步分析找到解決方案
在多次調整 innodb_adaptive_flushing 和 innodb_adaptive_flushing_method 后發現現象沒有任何變化。
這一點也比較容易解釋：因為大批量刷寫的原因是在於10秒循環中，innodb認為IO比較空閑，所以根據innodb_io_capacity 全力刷寫；而adaptive只發生在1秒循環中。
所以，調整adaptive相關參數實際上不解決問題。
從Step3中的分析可以得出一個比較明顯的結論，減小innodb_io_capacity 后就能很大程度上解決問題。
當我們把innodb_io_capacity從10000調整到200后，並且添加以下配置后：
innodb_adaptive_flush=OFF;
innodb_adaptive_checkpoint=keep_average
可以看到mysql的data written寫入量大量減少，且保持穩定（見下圖，7:31后是參數調整后的結果）
同時從flashcard的硬件寫入量來看，也大量的減少（見下圖）
參考資料：
http://www.mysqlperformanceblog.com/2011/03/31/innodb-flushing-a-lot-of-memory-and-slow-disk/
https://www.google.com/reader/view/#stream/feed%2Fhttp%3A%2F%2Fwww.xaprb.com%2Fblog%2Ffeed%2F
http://www.mysqlperformanceblog.com/2012/09/10/adaptive-flushing-in-mysql-5-6-cont/
http://dimitrik.free.fr/blog/archives/04-01-2012_04-30-2012.html#143
https://www.google.com/reader/view/#stream/feed%2Fhttp%3A%2F%2Fplanet.mysql.com%2Frss20.xml