【案例】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.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 飆高。
開發反饋某產品的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.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 飆高。
來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/22664653/viewspace-1259178/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- 動態改變quartz的觸發器策略?quartz觸發器
- 優化案例--重建索引引發的sql效能問題優化索引SQL
- 「前端 BUG 錄」變更 UI 庫主題引發的問題前端UI
- vue 變數賦值同時改變的問題Vue變數賦值
- raid問題AI
- RAID卡AI
- 10g RMAN的REDUNDANCY策略改變
- 【案例】常駐查詢引發的thread pool 效能問題之二thread
- 【案例】常駐查詢引發的thread pool 效能問題之一thread
- [問題]使用operator.eq(expect,res1)後改變了引數型別型別
- 微軟改變資料訪問策略 OLE DB再次轉向ODBCOS微軟
- Oracle 12C TDE問題引發DG不同步案例分析Oracle
- 關於 PHP Session ID 改變的問題解決PHPSession
- 從錯誤的RAID5中發現的問題AI
- reflow和repaint引發的效能問題AI
- 專案叢集引發的問題
- chrome打字卡的問題Chrome
- 函式呼叫引數變數傳值的問題函式變數
- sql優化案例:改變表的寫法使代價和邏輯讀降下來SQL優化
- 再分享兩個小問題變成大故障的案例
- RAID 儲存策略AI
- JS語法: 由++[[]][+[]]+[+[]] = 10 ?引發的問題JS
- Oracle優化案例-IB網及會話登陸審計引發的效能問題(十七)Oracle優化會話
- CNN實現手寫數字識別並改變引數進行分析CNN
- 改變無法改變的Query 變數變數
- vue-router watch 監聽路由引數改變觸發函式Vue路由函式
- Linux RAID卡優化LinuxAI優化
- Mybatis 一級快取和引發的問題MyBatis快取
- JS中缺少分號可能引發的問題JS
- sql server datediff函式引發的效能問題SQLServer函式
- Mybatis+0+null,小問題引發的血案MyBatisNull
- Qt 之 WindowFlags 引發的有趣問題一則QT
- 開啟mysql審計後引發的問題MySql
- IP地址修改後,DNS解析引發的問題DNS
- 使用DBMS_RANDOM過程引發的問題random
- 資料量大引發的disconnect Issue問題
- 重寫陣列的方法(改變原陣列)陣列
- NGUI和UGUI改變字型顏色的寫法NGUIUGUI