【Mysql】JDB2導致磁碟io使用率高 導致mysql延遲過高

小亮520cl發表於2016-07-22
參考連線:

背景:某專案slave資料庫的延遲非常大

  1. mysql> show slave status\G;
    *************************** 1. row ***************************
                   Slave_IO_State: Queueing master event to the relay log
                      Master_Host: 192.168.10.2
                      Master_User: repluser
                      Master_Port: 3306
                    Connect_Retry: 60
                  Master_Log_File: mysql-bin.000047 
              Read_Master_Log_Pos: 1029469531                    -----讀取的位置也在不停增大
                   Relay_Log_File: mysqlrelay.000201
                    Relay_Log_Pos: 614671683
            Relay_Master_Log_File: mysql-bin.000047
                 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: 614671473             ---執行的位置在不停增大,透過這個現象基本可以排除卡在主庫大事務的這個原因了
                  Relay_Log_Space: 1029471060
                  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: 242580    ---延遲也在不停增大
初步分析:sql執行緒執行速度趕不上io執行緒拉去日誌的速度,隨著時間的推移slave延遲越來越大

按照常規最佳化手段最佳化

  1. 參考文章:
  2. http://blog.itpub.net/29096438/viewspace-2057127/  
  3. http://blog.itpub.net/29096438/viewspace-2055014/
排除:因update語句缺少主鍵導致slave延遲,主庫進行大事務導致的salve延遲這兩個原因


檢視磁碟io狀況

  1. 如下:
  2. [root@Yun-MySQL02 ~]# iostat -dtxNm 2 10
    Linux 2.6.32-431.el6.x86_64 (Yun-MySQL02)       07/22/2016      _x86_64_        (4 CPU)

    07/22/2016 05:41:23 PM
    Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
    sdb               0.01   110.01    3.35   71.07     0.39     0.71    30.17     0.01    14.08   12.73  100%
    sda               0.01     2.41    0.13    0.36     0.01     0.01    75.79     0.01   25.07   3.64   0.18
    VolGroup0-LogVol01     0.00     0.00    0.13    2.76     0.01     0.01    12.67     0.23   80.89   0.61   0.18
    VolGroup0-LogVol00     0.00     0.00    0.00    0.01     0.00     0.00     8.00     0.00   16.45   0.70   0.00
    VolGroup1-LogVol00     0.00     0.00    3.36  181.08     0.39     0.71    12.17     0.36    14.94   12.10  100%


    07/22/2016 05:41:25 PM
    Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
    sdb               0.00    86.00    8.50  126.00     0.16     0.83    15.11     2.71   20.25   17.40  99.50
    sda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
    VolGroup0-LogVol01     0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
    VolGroup0-LogVol00     0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
    VolGroup1-LogVol00     0.00     0.00    8.50  211.50     0.16     0.83     9.22     5.01   22.80   14.52  99.50

  3. 檢視iotop狀況:
  4. Total DISK READ: 11.59 K/s | Total DISK WRITE: 877.24 K/s
      TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND                                                                                                                             
      873 be/3 root        0.00 B/s    3.86 K/s  0.00 % 77.79 % [jbd2/dm-2-8]
    31764 be/4 mysql       0.00 B/s  104.34 K/s  0.00 % 37.01 % mysqld --defaults-file=/data/mydata/my.cnf --basedir=/home/data/mys~ta/3306/mysql.pid --socket=/data/mydata/3306/mysql.sock --port=3306
    31765 be/4 mysql      11.59 K/s  146.85 K/s  0.00 % 28.39 % mysqld --defaults-file=/data/mydata/my.cnf --basedir=/home/data/mys~ta/3306/mysql.pid --socket=/data/mydata/3306/mysql.sock --port=3306
     2714 be/4 root        0.00 B/s    0.00 B/s  0.00 %  1.18 % [nfsd]

  5. 可以看到io相當繁忙,iowait也很高,並且[jbd2/dm-2-8]佔用了io很大的資源


最佳化sql
  1. iowait隨機io那麼高,那麼我們最佳化sql,結果發現沒效果

其它方法
  1. iotop [jbd2/dm-2-8]過高,搜尋了一下,還真發現一篇文章,是ext4檔案系統的一個bug,修復過後 slave延遲果然開始降低了
  2. 付參考連結:


後續:

  1. 修復上訴bug後情況仍不見好轉,用dstat命令看下io前幾名的程式
  2. [root@Yun-MySQL02 fiodir]# dstat -r -l -t --top-io
  3.  read  writ| 1m   5m  15m |  date/time   |  block i/o process   
    1.00   134 |2.10 2.19 2.21|26-07 15:42:23|mysqld     4096B  176k
    1.00   142 |2.10 2.19 2.21|26-07 15:42:24|mysqld     4096B  128k
    1.00   118 |2.17 2.20 2.21|26-07 15:42:25|mysqld     4096B  176k
       0   133 |2.17 2.20 2.21|26-07 15:42:26|mysqld        0   192k
       0   119 |2.17 2.20 2.21|26-07 15:42:27|mysqld        0   172k
    1.00   116 |2.17 2.20 2.21|26-07 15:42:28|mysqld     4096B  124k
    1.00   132 |2.17 2.20 2.21|26-07 15:42:29|nfsd       4096B 2000k
    1.00  77.0 |2.16 2.20 2.21|26-07 15:42:30|mysqld     4096B  188k
       0   135 |2.16 2.20 2.21|26-07 15:42:31|nfsd          0  2000k

  4. nfs檔案系統也佔用了大量的io,不知道是不是這個的原因,換到另一塊盤問題解決!

過了一段時間發現情況再次出現

  1. 檢視iostat狀態  
    1. sdb 0.00 1.98 0.00 8.91 0.00 51.49 11.56 0.40 44.56 0.00 44.56 17.44      15.54
    2. sdb 0.00 2.02 0.00 3.03 0.00 32.32 21.33 0.06 18.33 0.00 18.33 18.33      5.56
    3. sdb 0.00 0.00 2.00 0.00 32.00 0.00 32.00 0.09 9.00 9.00 0.00 43.00         8.60
    4. sdb 0.00 2.00 1.00 3.00 16.00 32.00 24.00 0.07 35.25 11.00 43.33 18.25     7.30
    5. sdb 0.00 2.00 7.00 3.00 176.00 36.00 42.40 0.14 14.40 10.71 23.00 10.80      10.80
    6. sdb 0.00 2.02 2.02 3.03 32.32 28.28 24.00 0.19 37.80 25.50 46.00 37.80      19.09
    7. sdb 0.00 1.98 0.00 2.97 0.00 19.80 13.33 0.07 24.33 0.00 24.33 24.33      7.23
    8. sdb 0.00 2.00 6.00 3.00 368.00 28.00 88.00 0.14 15.11 12.33 20.67 13.56      12.20
    9. sdb 0.00 1.98 0.99 2.97 15.84 35.64 26.00 0.07 18.25 8.00 21.67 18.25      7.23
    10. sdb 0.00 2.02 1.01 3.03 16.16 28.28 22.00 0.05 12.25 17.00 10.67 12.75      5.15
    11. sdb 0.00 8.00 3.00 5.00 48.00 456.00 126.00 0.27 33.62 14.00 45.40 22.38     17.90
    12. sdb 0.00 2.00 6.00 3.00 208.00 28.00 52.44 0.13 14.89 17.00 10.67 5.33      4.80
    13. sdb 0.00 2.02 1.01 3.03 16.16 24.24 20.00 0.08 20.25 9.00 24.00 20.25      8.18
    14. sdb 0.00 2.00 2.00 3.00 32.00 28.00 24.00 0.07 14.60 13.50 15.33 14.60     7.30
    15. sdb 0.00 2.00 4.00 3.00 64.00 52.00 33.14 0.09 13.00 11.50 15.00 13.00     9.10
    16. sdb 0.00 0.00 2.02 0.00 32.32 0.00 32.00 0.03 13.00 13.00 0.00 17.00           3.43
    17. sdb 0.00 2.00 10.00 3.00 3728.00 32.00 578.46 0.22 17.46 15.40 24.33 7.08     9.20
    18. sdb 0.00 1.98 3.96 2.97 63.37 31.68 27.43 0.13 18.29 16.00 21.33 18.71      12.97

    19. util基本1秒一波動,很符合log_buffer寫資料到log_file的規律(每隔1秒寫入)
    檢視innodb狀態(oradba 或者 dodba 或者指令碼)
    1. -------- ---innodb bp pages status-- -----innodb data status---- --innodb log--   his --log(byte)--  read ---query--- 
        time  |   data   free  dirty flush| reads writes  read written|fsyncs written| list uflush  uckpt  view inside  que|
      15:52:27| 596582   8168  11939   797|    31   1034   496k  27.9m|   219    3.0m| 2430    998   70.9m    0     0     0|
      15:52:29| 596575   8172  11553   910|    48   1090   768k  30.7m|   162    9.2m| 2467    25k   73.0m    1     0     0|
      15:52:30| 596578   8167  11283   824|    43   1018   688k  28.2m|   179    2.4m| 2619     1k   54.7m    1     0     0|
      15:52:31| 596557   8179  10976   831|    44   1017   704k  28.3m|   168    10 m| 2612     4k   57.0m    3     0     0|
      15:52:32| 596546   8187  10840   743|    25    945   400k  25.7m|   186    9.0m| 2720     1k   59.4m    1     0     0|
      15:52:33| 596662   8066  10400  1168|   158   1398   2.5m  39.4m|   206    5.0m| 2768     1k   62.2m    2     0     0|
  2. 可以看到Innodb_data_written每秒的寫入量很穩定,沒什麼大的波動,但是Innodb_os_log_written的波動比較頻繁
    1. 結合上iostat中 wsec/s 較大的數值,基本可以確定IO高負載的元兇是redo log的flush,而不是data page的flush


  1. 檢視innodb log buffer狀態
    1. mysql> show global status where variable_name in('Innodb_log_waits','Innodb_buffer_pool_wait_free');
    2. +------------------------------+-------+
    3. | Variable_name | Value |
    4. +------------------------------+-------+
    5. | Innodb_buffer_pool_wait_free | 0 |
    6. | Innodb_log_waits | 2560 | ####log buffer過小導致寫日誌等待數。單位是次。
    7. +------------------------------+-------+


加大log_buffer_pool與innodb_log_file_size的值,重啟資料庫,發現iowait降低,slave開始下降!



總結:最佳化io過高的幾種原因:
1.是否是buffer pool過小導致的              參考文章:葉金榮--是什麼導致磁碟io過高 http://mp.weixin.qq.com/s/sAGFo-h1GCBhad1r1cEWTg
2.是否是sql導致的
3.innodb_io_captiy對io穩定性的影響     http://blog.itpub.net/29096438/viewspace-2134208/
4.其它系統原因




來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/29096438/viewspace-2122409/,如需轉載,請註明出處,否則將追究法律責任。

相關文章