處理mysql複製故障一例薦

今天一個主從複製的伺服器出現了問題，資料和主伺服器不一樣，但是複製程式是對的。開始我只看了複製程式，沒有太注意，原始內容如下：

 

mysql> show slave statusG 
*************************** 1. row *************************** 
               Slave_IO_State: Waiting for master to send event 
                  Master_Host: 192.168.125.9 
                  Master_User: slave 
                  Master_Port: 9188 
                Connect_Retry: 10 
              Master_Log_File: mysql-bin.000004 
          Read_Master_Log_Pos: 805036116 
               Relay_Log_File: localhost-relay-bin.000018 
                Relay_Log_Pos: 192473825 
        Relay_Master_Log_File: mysql-bin.000004 
             Slave_IO_Running: Yes 
            Slave_SQL_Running: Yes 
              Replicate_Do_DB:  
          Replicate_Ignore_DB:  
           Replicate_Do_Table:  
       Replicate_Ignore_Table:  
      Replicate_Wild_Do_Table:  
  Replicate_Wild_Ignore_Table:  
                   Last_Errno: 0 
                   Last_Error:  
                 Skip_Counter: 0 
          Exec_Master_Log_Pos: 197587108 
              Relay_Log_Space: 805036869 
              Until_Condition: None 
               Until_Log_File:  
                Until_Log_Pos: 0 
           Master_SSL_Allowed: No 
           Master_SSL_CA_File:  
           Master_SSL_CA_Path:  
              Master_SSL_Cert:  
            Master_SSL_Cipher:  
               Master_SSL_Key:  
        Seconds_Behind_Master: 25236 
Master_SSL_Verify_Server_Cert: No 
                Last_IO_Errno: 0 
                Last_IO_Error:  
               Last_SQL_Errno: 0 
               Last_SQL_Error:  
1 row in set (0.00 sec) 

後來發現資料不對，發現

Read_Master_Log_Pos和Exec_Master_Log_Pos真麼差別這麼大，原理上，應該是挨著的， 然後開始找問題，把日誌翻來覆去的看，沒有發現任何問題，然後看了一下processlist： ，發現延遲了5個多小時，我的個娘耶。

mysql> show processlistG 
*************************** 1. row *************************** 
     Id: 1 
   User: root 
   Host: localhost 
     db: NULL 
Command: Query 
   Time: 0 
  State: NULL 
   Info: show processlist 
*************************** 2. row *************************** 
     Id: 2 
   User: system user 
   Host:  
     db: NULL 
Command: Connect 
   Time: 1038 
  State: Waiting for master to send event 
   Info: NULL 
*************************** 3. row *************************** 
     Id: 3 
   User: system user 
   Host:  
     db: NULL 
Command: Connect 
   Time: 18697
  State: freeing items 
   Info: NULL 
3 rows in set (0.00 sec) 

基本確認主庫和從庫是延遲，而不是認為或者其他bug之類的東西。

開始找延遲的原因吧：

1、檢查網路延時：

[root@localhost var]# ping 192.168.125.9 
PING 192.168.125.9 (192.168.125.9) 56(84) bytes of data. 
64 bytes from 192.168.125.9: icmp_seq=1 ttl=64 time=0.555 ms 
64 bytes from 192.168.125.9: icmp_seq=2 ttl=64 time=0.588 ms 
64 bytes from 192.168.125.9: icmp_seq=3 ttl=64 time=0.635 ms 
64 bytes from 192.168.125.9: icmp_seq=4 ttl=64 time=0.588 ms 
64 bytes from 192.168.125.9: icmp_seq=5 ttl=64 time=0.586 ms 

沒有發現問題。

2、檢查系統資源

 

[root@localhost var]# iostat -dx 1 5 
Linux 2.6.18-164.el5PAE (localhost.localdomain)         11/18/2011 
 
Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda               0.07    40.80  0.22 123.53     6.06  1314.72    10.67     0.98    7.92   2.74  33.97 
sda1              0.01     0.00  0.00  0.00     0.02     0.00    18.93     0.00    2.33   1.60   0.00 
sda2              0.00     0.00  0.00  0.00     0.01     0.00    36.13     0.00    3.65   2.81   0.00 
sda3              0.02     0.01  0.00  0.01     0.02     0.16    20.21     0.00    5.36   2.71   0.00 
sda4              0.00     0.00  0.00  0.00     0.00     0.00     2.00     0.00   21.00  21.00   0.00 
sda5              0.04    40.79  0.22 123.52     6.01  1314.56    10.67     0.98    7.92   2.74  33.96 
 
Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda               0.00   156.00  2.00 365.00    16.00  4160.00    11.38     3.15    8.64   2.68  98.30 
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda5              0.00   156.00  2.00 365.00    16.00  4160.00    11.38     3.15    8.64   2.68  98.30 
 
Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda               0.00   112.00  0.00 315.00     0.00  3448.00    10.95     2.52    8.06   3.13  98.70 
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda5              0.00   112.00  0.00 315.00     0.00  3448.00    10.95     2.52    8.06   3.13  98.70 
 
Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util 
sda               0.00   103.96  0.00 195.05     0.00  2392.08    12.26     3.12   15.47   5.06  98.71 
sda1              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda2              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda3              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda4              0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00 
sda5              0.00   103.96  0.00 195.05     0.00  2392.08    12.26     3.12   15.47   5.06  98.71 

發現有IO，但是不太厲害，算正常。

然後看CPU，使用top命令

Tasks: 141 total,   1 running, 139 sleeping,   1 stopped,   0 zombie 
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
Cpu1  :  0.3%us,  0.3%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
Cpu3  :  0.0%us,  4.7%sy,  0.0%ni, 94.7%id,  0.0%wa,  0.0%hi,  0.7%si,  0.0%st 
Cpu4  :  0.0%us,  1.3%sy,  0.0%ni,  1.0%id, 97.3%wa,  0.3%hi,  0.0%si,  0.0%st 
Cpu5  :  0.0%us,  0.3%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st 
Cpu6  :  0.0%us,  0.0%sy,  0.0%ni, 91.3%id,  0.0%wa,  3.7%hi,  5.0%si,  0.0%st 
Cpu7  :  0.3%us,  7.0%sy,  0.0%ni, 81.8%id,  0.0%wa,  1.0%hi,  9.9%si,  0.0%st 
Mem:   4139196k total,  2605768k used,  1533428k free,   215052k buffers 
Swap:  8385920k total,        0k used,  8385920k free,  2143992k cached 

發現

Cpu4  :  0.0%us,  1.3%sy,  0.0%ni,  1.0%id, 97.3%wa,  0.3%hi,  0.0%si,  0.0%st  這個核有點問題 

wait太高的，話，應該是cpu在等待IO資源，導致的。 但是IO資源又不太高，才幾M的寫入。 不過現在也沒辦法，只有想法降低mysql的寫入來試試看。  我關閉了slave更新bin-log的功能 #log-slave-updates  然後重啟mysql，啟動slave程式。現在Slave_SQL程式速度加快了，明顯看見 Exec_Master_Log_Pos數增加，show processlist中的時間也在縮短， 過了有20多分鐘，資料同步完成了。通過maatkit工具檢查，沒有問題。  故障現在是修復了，不過為什麼mysql的IO那麼低，卻會導致IO資源缺乏，我嘗試通過寫檔案來測試磁碟IO，應該可以達到130多M/s。 這個問題現在比較詭異了，估計是mysql slave只能使用單核導致的，而這臺伺服器雖然是8核的，但是單核的主頻只有2.13，中繼sql，執行sql，寫入自己的blog，IO請求都在一個核上，導致的資源不足。

在補充一下，這個機器業務空閒後，我做了一個基準測試，發現效率還是上不去。找了硬體的原因，也懷疑過編譯引數，在相同硬體平臺和mysql版本做了相關測試。最後發現這次效能問題的最終殺手是my.cnf的一個配置。這次心血來潮加了如下一個引數

sync_binlog=1  //意思是即時同步binlog到硬碟上，不快取日誌，目的是避免硬體故障或者軟體故障導致binlog沒有即時寫盤而丟失。但是開始沒想到這個引數在QPS上到100左右後，效能消耗是如此的高，導致整個CPU核都在等待IO，建議大家以後不是特別需要，還是別碰這個引數了，預設是0，由作業系統來排程什麼時候寫入到硬碟，或者將值調整到比較大。

還有一個就是innodb引擎的

innodb_flush_log_at_trx_commit = N

N=0  – 每隔一秒，把事務日誌快取區的資料寫到日誌檔案中，以及把日誌檔案的資料重新整理到磁碟上；

N=1  – 每個事務提交時候，把事務日誌從快取區寫到日誌檔案中，並且重新整理日誌檔案的資料到磁碟上；

 

N=2  – 每事務提交的時候，把事務日誌資料從快取區寫到日誌檔案中；每隔一秒，重新整理一次日誌檔案，但不一定重新整理到磁碟上，而是取決於作業系統的排程；

如果設定為1，效率也會相當的低，建議設定到2，如果想要效能再提交，可以設定為0.

 

具體可以參見如下文章：http://www.mysqlops.com/2011/10/26/mysql-variable-third.html