性能测试案例分析——连接池性能优化

背景

惠惠www.huihui.cn社区1.0性能测试
服务强依赖于mysql, 许多接口都会请求mysql

对mysql的请求用GenericObjectPool的连接池来进行管理, 设置如下：

79             connectionPool.setMaxActive(maxActive);
80             connectionPool.setTestOnBorrow(false);
81             connectionPool.setTestOnReturn(true);
82             connectionPool.setTestWhileIdle(true);
83             connectionPool
84                 .setMinEvictableIdleTimeMillis(minEvictableIdleTimeMillis);
85
86             // Start the Evictor
87             connectionPool
88                 .setTimeBetweenEvictionRunsMillis(timeBetweenEvictionRunsMillis);

问题

用100并发打压服务，发现拿到连接并在干活的线程数只有10+, 而其余80+的线程wait在borrowObject的逻辑, 相应的stack如下：

有许多线程在blocked在makeObject相关的逻辑，均在等一把锁
1462 "resin-tcp-connection-*:3231-321" daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor entry [0x00000000507ff000]
1463    java.lang.Thread.State: BLOCKED (on object monitor)
1464         at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
1465         - waiting to lock <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
1466         at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
1467         at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
1468         at outfox.cps.dao.source.CpsDataSource.getConnection(CpsDataSource.java:61)
1469         at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
1470         at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
1471         at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:572)
1472         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:636)
1473         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:665)
1474         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:673)
1475         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
1476         at outfox.cps.dao.impl.FriendshipDaoImpl.getFansWithTime(FriendshipDaoImpl.java:93)
......

有一个线程拿到了makeObject相关的锁，并在执行相关的逻辑
1208 "resin-tcp-connection-*:3231-149" daemon prio=10 tid=0x000000004d67e800 nid=0x66d7 runnable [0x000000005180f000]
1209    java.lang.Thread.State: RUNNABLE
1210         at java.net.SocketInputStream.socketRead0(Native Method)
1211         at java.net.SocketInputStream.read(SocketInputStream.java:129)
1212         at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
1213         at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
1214         at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
1215         - locked <0x000000009f5a4cc8> (a com.mysql.jdbc.util.ReadAheadInputStream)
1216         at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2329)
1217         at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2774)
1218         at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2763)
1219         at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3299)
1220         at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1837)
1221         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1961)
1222         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2537)
1223         - locked <0x000000009f5a1600> (a java.lang.Object)
1224         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2466)
1225         at com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1383)
1226         - locked <0x000000009f5a1600> (a java.lang.Object)
1227         at com.mysql.jdbc.ConnectionImpl.loadServerVariables(ConnectionImpl.java:3752)
1228         at com.mysql.jdbc.ConnectionImpl.initializePropsFromServer(ConnectionImpl.java:3345)
1229         at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2046)
1230         at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:729)
1231         at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:46)
1232         at sun.reflect.GeneratedConstructorAccessor26.newInstance(Unknown Source)
1233         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
1234         at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
1235         at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
1236         at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:302)
1237         at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:283)
1238         at java.sql.DriverManager.getConnection(DriverManager.java:582)
1239         at java.sql.DriverManager.getConnection(DriverManager.java:207)
1240         at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:46)
1241         at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
1242         - locked <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory)
1243         at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
1244         at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
1245         at outfox.cps.dao.source.CpsDataSource.getConnection(CpsDataSource.java:61)
1246         at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
1247         at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
1248         at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:572)
1249         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:636)
1250         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:665)
1251         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:673)
1252         at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
1253         at outfox.cps.dao.impl.FriendshipDaoImpl.getAttentionsWithTime(FriendshipDaoImpl.java:69)
1254         at outfox.cps.api.impl.FriendshipApi$RelationListOperation.copyRealtionListFromDbToRedis(FriendshipApi.java:118)
1255         at outfox.cps.api.impl.FriendshipApi$RelationListOperation.getRelationList(FriendshipApi.java:144)
......

分析

为什么maxActive设置为100, 还会有如此多的线程在makeObject?这是我们的setMaxActive没有生效, 还是GenericObjectPool有其他destroy对象的机制被我们忽略了?

查看GenericObjectPool的java doc, 了解对象池关于对象创建和销毁相关的方式以及配置方式

打压开始后, 动态debug, 发现pool对象有许多我们未进行配置的成员变量，对照doc逐一check各变量
发现一个可怀疑点: maxIdle, 其值一直在2-8之间波动, 且doc中如是描述:

maxActive controls the maximum number of objects that can be borrowed from the pool at one time. When non-positive, there is no limit to the number of objects that may be active at one time. When maxActive is exceeded, the pool is said to be exhausted. The default setting for this parameter is 8.
maxIdle controls the maximum number of objects that can sit idle in the pool at any time. When negative, there is no limit to the number of objects that may be idle at one time. The default setting for this parameter is 8.

可知默认的maxIdle值为8，若未进行配置，当pool中idle的object超过默认值8时，多余的对象就会被destroy
至此，问题基本定位到

验证

增加对maxIdle的配置，即：

79             connectionPool.setMaxActive(maxActive);
80             connectionPool.setMaxIdle(maxActive);    //实际中可以设小一些, 如30
81             connectionPool.setTestOnBorrow(false);
82             connectionPool.setTestOnReturn(true);
83             connectionPool.setTestWhileIdle(true);
84             connectionPool
85                 .setMinEvictableIdleTimeMillis(minEvictableIdleTimeMillis);
86
87             // Start the Evictor
88             connectionPool
89                 .setTimeBetweenEvictionRunsMillis(timeBetweenEvictionRunsMillis);

重新打压, 发现吞吐增长近一倍，响应速度也显著加快，stack中无线程blocked在borrowObject或makeObject相关的逻辑

另一个重要的问题

未设置maxWait, doc中对maxWait说明如下：

setMaxWait

public void setMaxWait(long maxWait)
Sets the maximum amount of time (in milliseconds) the borrowObject() method should block before throwing an exception when the pool is exhausted and the "when exhausted" action is WHEN_EXHAUSTED_BLOCK. When less than or equal to 0, the borrowObject() method may block indefinitely.
Parameters:
maxWait - maximum number of milliseconds to block when borrowing an object.
See Also:
getMaxWait(), setWhenExhaustedAction(byte), WHEN_EXHAUSTED_BLOCK

可知若不进行设置，当被依赖的服务由于某些故障（如机器资源被某进程大量占用）而响应极慢时，会有大量线程blocked在borrowObject的逻辑，最终导致resin线程耗尽，服务卡死，用户请求被拒绝
可参考之前的一次线上故障：购物搜索变慢导致依赖于它的购物助手web卡死，其原因为助手请求搜索时的连接池未对borrowObject设置timeout，导致大量线程blocked在borrowObject的逻辑
因此需要对maxWait进行设置，且设置的时间不宜过大(高吞吐时仍有可能导致web卡死)，也不宜过小（可能导致较多的请求失败），具体的配置可参考如下：

基本原则：
qt<N, 其中q为服务最大吞吐(请求/s), t为设置的maxWait时间(s), N为resin的最大线程数

购物resin的线程数当前为512, 预估最大吞吐为100, 因此有t<N/q=512/100=5.12
我们将其配置为3s(即3000ms), 从而当该对象池中的对象出现异常时，仍可扛住512/3约为170qps的压力

具体的配置如下：

79             connectionPool.setMaxActive(maxActive);
80             connectionPool.setMaxIdle(maxActive);
81             connectionPool.setMaxWait(maxWait);    // maxWait=3000
82             connectionPool.setTestOnBorrow(false);
83             connectionPool.setTestOnReturn(true);
84             connectionPool.setTestWhileIdle(true);
85             connectionPool
86                 .setMinEvictableIdleTimeMillis(minEvictableIdleTimeMillis);
87
88             // Start the Evictor
89             connectionPool
90                 .setTimeBetweenEvictionRunsMillis(timeBetweenEvictionRunsMillis);