【案例】RAID卡寫政策改變引發的問題

一 現象描述

     開發回報某産品的agent 的程序hang在某些線程上,檢視日志,agent  master 累積很多未處理的消息隊列。在17:00 – 21:00 之間，有一定程度的寫入量低峰，猜測可能是寫入資料庫變慢了，不過從目前得到的資訊來看無法完全确定。

"pool-10-thread-12" prio=10 tid=0x000000005f36d000 nid=0x1d81 runnable [0x00000000441de000]

   java.lang.thread.state: runnable

     at java.net.socketinputstream.socketread0(native method)

     .......

     at com.mysql.jdbc.util.readaheadinputstream.read(readaheadinputstream.java:189)

     - locked <0x00002aaab6da9758> (a com.mysql.jdbc.util.readaheadinputstream)

    .....

     at com.mysql.jdbc.mysqlio.sqlquerydirect(mysqlio.java:2140)

     at com.mysql.jdbc.connectionimpl.execsql(connectionimpl.java:2626)

     - locked <0x00002aaab6da9b30> (a java.lang.object)

     at com.mysql.jdbc.preparedstatement.executeinternal(preparedstatement.java:2111)

     at com.mysql.jdbc.preparedstatement.executeupdate(preparedstatement.java:2407)

     at org.apache.commons.dbcp.delegatingstatement.executebatch(delegatingstatement.java:297)

     at org.springframework.jdbc.core.jdbctemplate.execute(jdbctemplate.java:619)

     at org.springframework.jdbc.core.jdbctemplate.batchupdate(jdbctemplate.java:866)

     at org.apache.mina.core.filterchain.defaultiofilterchain$entryimpl$1.messagereceived(defaultiofilterchain.java:793)

     at org.apache.mina.core.filterchain.iofilterevent.fire(iofilterevent.java:71)

     at org.apache.mina.core.session.ioevent.run(ioevent.java:63)

  .......

     at org.apache.mina.filter.executor.orderedthreadpoolexecutor$worker.run(orderedthreadpoolexecutor.java:714)

     at java.lang.thread.run(thread.java:619)

二 問題分析

   業務代碼層面:檢視程序堆棧發現,用于處理 handler 的線程池全部耗盡，并且都在處理資料庫的操作 ，導緻 agent後續上報的監控資料或者心跳都不能及時被 master接受，agent 也就被hang住！

    資料庫層面：檢查資料庫服務端的max_connections 為1024 遠大于應用連接配接池配置的16。

   分析到這裡，簡單來看隻要加大應用程式的連接配接池線程數即可！但是思考一下，為什麼3個多月運作平穩，反而現在出現異常？agent 等待資料被處理，說明涉及到資料庫相關操作處理速度緩慢，而一般響應慢，有以下原因：

1 sql程式不夠優化，需要調整索引結構或者應用通路資料庫方式，比如增加緩存。

2 os 磁盤io異常，導緻通路資料慢。   

對于 本例 應用為寫入型insert 居多,而無優化空間。到伺服器上檢視io使用率：{資料}

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

              14.31    0.00     4.82        19.67    0.00    61.20

device:     rrqm/s   wrqm/s  r/s         w/s       rkb/s      wkb/s    avgrq-sz  avgqu-sz     await  svctm   %util

sda          0.02     143.19   18.47    199.18  1487.19  2673.67    38.23    435.77      3.55   3.22     99.5

%util 已經跑滿，r/s 為17  。

我們資料庫伺服器的配置為 12塊的300g 的sas  盤做raid10,最大可以支撐3k-5k   tps。

root@rac1 # megacli -ldinfo -lall -aall  

adapter 0 -- virtual drive information:

virtual disk: 0 (target id: 0)

name:

raid level: primary-1, secondary-0, raid level qualifier-0

....

default cache policy: writeback, readaheadnone, direct, no write cache if bad bbu

current cache policy: writeback, readaheadnone, direct, no write cache if bad bbu

access policy: read/write

disk cache policy: disabled

檢視raid 卡的日志表明，磁盤的io政策由于raid卡充放電的原因由wb改為wt。 

root@rac1#megacli  -fwtermlog dsply -aall

11/08/14  3:36:58: prcallback: pr completed for pd=0a

11/08/14  3:36:58: pr cycle complete

11/08/14  3:36:58: evt#14842-11/03/12  3:36:58:  35=patrol read complete

11/08/14  3:36:58: next pr scheduled to start at 11/10/12  3:01:59 

11/08/14  0:48:04: evt#14843-11/04/12  0:48:04:  44=time established as 11/04/12  0:48:04; (25714971 seconds since power on)

11/08/14 15:30:13: evt#14844-11/05/12 15:30:13: 195=bbu disabled; changing wb virtual disks to wt  ---問題的原因

11/08/14 15:30:13: change in current cache property detected for ld : 0!

11/08/14 15:30:13: evt#14845-11/05/12 15:30:13:  54=policy change on vd 00/0 to [id=00,dcp=0d,ccp=0c,ap=0,dc=0,dbgi=0,s=0|0] from [id=00,dcp=0d,ccp=0d,ap=0,dc=0,dbgi=0,s=0|0]

抽絲剝繭之後，明顯是磁盤raid 卡充電将磁盤的寫政策有write back 修改為write through ，io性能急劇下降導緻應用層的線程等待問題。

三 拓展

   介紹一點 raid 卡知識

   raid卡都有寫cache(battery backed write cache),寫cache對io性能的提升非常明顯,因為掉電會丢失資料,是以必須由電池提供支援。電池會定期充放電,一般為90天左右,當發現電量低于某個閥值時,會将寫cache政策從writeback置為writethrough,相當于寫cache會失效,這時如果系統有大量的io操作,可能會明顯感覺到io響應速度變慢,cpu 隊列堆積系統load 飙高。