今天幫網友處理了一個關於binlog增量恢復很慢的問題。
問題描述：
  網友是先通過xtrabackup將mysql全量恢復到測試環境中，然後再增量恢復binlog，具體操作為：用mysqlbinlog -v -v --base64-output=DECODE-ROWS解析binlog到一個sql檔案中，然後再將sql檔案應用到mysql中。在binlog增量恢復時非常慢，基於2分鐘才生成1M的binlog。

問題分析：
  1.我先要網友檢查並提供伺服器硬體資源使用情況，特別是IO，網友反應硬體資源很閒，沒有任何負載，IO情況如下：
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.00    0.00    0.00    0.00    0.00  100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
vda               0.00     0.00    1.00    0.00     0.01     0.00    16.00     0.01    8.00   8.00   0.80
vdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.00    0.00    0.00    0.00    0.00  100.00

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
vdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

上面說明IO很閒。
 2.請網友用show processlist提供mysql程序情況
網碼提供如下：
([email protected]) [(none)]>show processlist;
+----+------+-----------+------+---------+------+-------+------------------+
| Id | User | Host      | db   | Command | Time | State | Info             |
+----+------+-----------+------+---------+------+-------+------------------+
|  1 | root | localhost | test | Sleep   | 3348 |       | NULL             |
|  2 | root | localhost | NULL | Query   |    0 | init  | show processlist |
+----+------+-----------+------+---------+------+-------+------------------+
上面也沒有發現明顯異常.
3.請網友檢視解析出來的binlog中是些什麼操作
網友提供如下：
BINLOG '
q4ZxVxMBAAAAigAAABFSFQAAACiYBQAAAAEACndqZGJjZW50ZXIAE3dqX3RibF9tZW1iZXJfY2Fj
aGUAHggPAwMDDw8PCg8PDxIPDw/29vb29gMSEgESEvYBEiZIADwAlgDAADwAPADAAACWADwAPAAU
AhQCFAIUAhQCAAAAABQCAGARwDgoHXRQ
q4ZxVx8BAAAA6gEAAPtTFQAAACiYBQAAAAEAAgAe//////////8AAADAFzA0AAAAAAAA1gAAANcP
AAAFAAAABDgxMDgIMTAwMDAyMDIG6Z2e5rSyCosPA+eUtwnouqvku73or4ESNDUwMjIxMTk4OTA4
MTAyOTMymZP9XGggZDQxZDhjZDk4ZjAwYjIwNGU5ODAwOTk4ZWNmODQyN2UG5ZCv55SoCzEzNzY4
NTc1NzY2gAAAAAAAAAAAgAAAAAAAAAAAgAAAAAAAAAAAgAAAAAAAAAAAgAAAAAAABrAADgAAAJmU
oh4ImbR8AAAAmZjUpAeZmbhA7oAAAAAAAAAAAACZmbhA7gAAAMAXMDQAAAAAAADWAAAA1w8AAAUA
AAAEODEwOAgxMDAwMDIwMgbpnZ7mtLIKiw8D55S3Cei6q+S7veivgRI0NTAyMjExOTg5MDgxMDI5
MzKZk/1caCBkNDFkOGNkOThmMDBiMjA0ZTk4MDA5OThlY2Y4NDI3ZQblkK/nlKgLMTM3Njg1NzU3
NjaAAAAAAAAAAACAAAAAAAAAAACAAAAAAAAAAACAAAAAAAAAAACAAAAAAAAGsAAOAAAAmZSiHgiZ
tHwAAACZmNSkB5mZuED4gAAAAAAAAAAAAJmZuED4yYjykg==
5 QUERY COMMIT

上面應該沒有使用--base64-output=DECODE-ROWS轉換顯示內容，表面上看是沒有任何有用的資訊，但從5 QUERY COMMIT中的commit字眼提醒了我。

4.請網友提供檢視一下sync_binlog和innodb_flush_log_at_trx_commit兩個引數的設定是否都為1。
  網友很快回復引數有設定為1，同時有跟他確認了機器為虛擬機器，現在問題的原因應該就是這兩個引數的設定，因為我曾經同樣在測試環境的虛擬機器上測試過這兩個引數在不同值下的效能比較。詳見blog:http://blog.csdn.net/zengxuewen2045/article/details/51476186。
 期間我同時也懷疑恢復操作可能有大量的insert，而且是每插入一行，就commit一次，也跟網友說過：用show global status like 'Handler_commit';檢視一下commit次數，間隔一段時間檢視一次，確認值是否在不斷增加，不過這些資料沒有提供，不影響這個問題的處理。

問題解決：
  當發現上面引數設定為1後，將引數全都改為預設值(都改為0效能更好，反正測試嘛，安全不是重要的),就重新來一次全量恢復，再進行一次binlog增量恢復，這次速度很快。

下面是網友在QQ上的回覆：
午後單車(175686647)  16:52:06
果然快了非常多
午後單車(175686647)  17:00:03
@代言人    多謝哈，  看來還是缺乏經驗
要多測試
這個坑困擾我2天了
代言人(171057655)  17:02:48
不會吧
呵呵