一 现象描述
开发反馈某产品的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 飙高。
