PageHelper分页插件导致线上dubbo线程池爆满的排查,本文中的真实ip已经替换成127.0.0.1
前段时间一应用升级了公司的框架上线不久,监控系统抛出了大量警告。该系统也比较特殊,只有几个dubbo接口提供服务,但是请求量却特别大。
查看日志发现dubbo线程池爆满。抛出如下异常:
Thread pool is EXHAUSTED!
Thread Name: DubboServerHandler-127.0.0.1:20880,
Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200),
Task: 58475360 (completed: 58475160),
Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://127.0.0.1:20880!
通过监控系统观察到应用上线后,线程数量在不停的增加。
同时日志中还有大量的org.mybatis.spring.MyBatisSystemException异常。
于是怀疑是因为大量的异常,导致系统处理能力下降。大量的请求压满了dubbo线程池。
根据异常信息,最后定位到操作数据库时没有加数据校验,导致sql异常。修改代码重新上线后,监控系统不再立刻告警。
但是隔了一段时间后dubbo线程池又是爆满,并且新建线程数量还是呈梯形上升。只能立刻关闭流量不让请求过来。
由于框架中升级了dubbo的版本,担心是dubbo线程池有bug,根据异常信息查看了dubbo源码,发现AbortPolicyWithReport
这个类。会在线程池被占满后,打印堆栈信息,并保存在用户目录下。
com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport
private void dumpJStack() {
long now = System.currentTimeMillis();
//dump every 10 minutes
if (now - lastPrintTime < 10 * 60 * 1000) {
return;
}
if (!guard.tryAcquire()) {
return;
}
Executors.newSingleThreadExecutor().execute(new Runnable() {
@Override
public void run() {
String dumpPath = url.getParameter(Constants.DUMP_DIRECTORY, System.getProperty("user.home"));
SimpleDateFormat sdf;
String OS = System.getProperty("os.name").toLowerCase();
// window system don't support ":" in file name
if(OS.contains("win")){
sdf = new SimpleDateFormat("yyyy-MM-dd_HH-mm-ss");
}else {
sdf = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
}
String dateStr = sdf.format(new Date());
FileOutputStream jstackStream = null;
try {
jstackStream = new FileOutputStream(new File(dumpPath, "Dubbo_JStack.log" + "." + dateStr));
JVMUtil.jstack(jstackStream);
} catch (Throwable t) {
logger.error("dump jstack error", t);
} finally {
guard.release();
if (jstackStream != null) {
try {
jstackStream.flush();
jstackStream.close();
} catch (IOException e) {
}
}
}
lastPrintTime = System.currentTimeMillis();
}
});
}
查看Dubbo_JStack.log 文件内容如下,发现绝大多数的线程会执行到PageAutoDialect.getUrl
这个方法。
"DubboServerHandler-127.0.0.1:20880-thread-193" Id=366 RUNNABLE
at java.lang.Thread.setPriority0(Native Method)
at java.lang.Thread.setPriority(Thread.java:1092)
at java.lang.Thread.init(Thread.java:414)
at java.lang.Thread.init(Thread.java:349)
at java.lang.Thread.<init>(Thread.java:461)
at com.github.pagehelper.page.PageAutoDialect.getUrl(PageAutoDialect.java:159)
at com.github.pagehelper.page.PageAutoDialect.getDialect(PageAutoDialect.java:208)
at com.github.pagehelper.page.PageAutoDialect.initDelegateDialect(PageAutoDialect.java:81)
at com.github.pagehelper.PageHelper.skip(PageHelper.java:65)
at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:89)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy106.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at sun.reflect.GeneratedMethodAccessor173.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:434)
at com.sun.proxy.$Proxy81.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:239)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:126)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:68)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
查看代码发现,PageHelper分页插件中PageAutoDialect.getUrl
这段代码在公司的框架上被修改过。修改后的代码如下:
该方法:每次执行getUrl方法,都会创建一条新的线程,然后又通过FutureTask等待线程执行完成返回数据。然而这段是每次执行sql是都会被调用然后创建线程,这明显是有问题。并且线程启动后通过FutureTask#get()等待。看上去,似乎完全就是一个耗时、耗资源且无用操作。
经过压测证实这段代码确实存在性能问题。这也是为什么图1中,线程数量会呈现梯形递增的原因。
怎么可能写这样的代码???最后查看git提交记录发现,这个为了解决Sharding-Jdbc和PageHelper整合执行sql时,由于PageHelper在获取数据库方言时,会导致执行ShardingConnection#close()
方法,而清除Sharding-Jdbc的当前上下文信息。具体问题见issue: 5.0.1版本PageHelper导致ShardingJdbc强制分页失效
解决方案
通过搜索发现,调用getUrl方法的地方只有PageAutoDialect#getDialect
方法,而这个方法的返回值类型是AbstractHelperDialect
,于是想到缓存当前的数据库方言对象AbstractHelperDialect
,而不是每次调用getUrl然后判断数据库方言。
先看一下pagehelper中调用getUrl方法的源码
com.github.pagehelper.page.PageAutoDialect
源码:
private AbstractHelperDialect getDialect(MappedStatement ms) {
//改为对dataSource做缓存
DataSource dataSource = ms.getConfiguration().getEnvironment().getDataSource();
String url = getUrl(dataSource);
if (urlDialectMap.containsKey(url)) {
return urlDialectMap.get(url);
}
try {
lock.lock();
if (urlDialectMap.containsKey(url)) {
return urlDialectMap.get(url);
}
if (StringUtil.isEmpty(url)) {
throw new PageException("无法自动获取jdbcUrl,请在分页插件中配置dialect参数!");
}
String dialectStr = fromJdbcUrl(url);
if (dialectStr == null) {
throw new PageException("无法自动获取数据库类型,请通过 helperDialect 参数指定!");
}
AbstractHelperDialect dialect = initDialect(dialectStr, properties);
urlDialectMap.put(url, dialect);
return dialect;
} finally {
lock.unlock();
}
}
private String getUrl(DataSource dataSource) {
Connection conn = null;
try {
conn = dataSource.getConnection();
return conn.getMetaData().getURL();
} catch (SQLException e) {
throw new PageException(e);
} finally {
if (conn != null) {
try {
if (closeConn) {
conn.close();
}
} catch (SQLException e) {
//ignore
}
}
}
}
查看源码发现实际上pagehelper已经做了这样的缓存。但是缓存key却正是每次都会被调用的getUrl返回值,然后将其做为缓存key(也就是将当前数据库的连接地址做为key),value为数据库方言对象AbstractHelperDialect
。
然而这种做法却有两个问题:
- 为了获取当前数据库的url,每次都会从数据库连接池中获取连接,调用conn.getMetaData().getURL()才能拿到url。浪费连接池资源。
- 数据库url是不变的,却每次重复调用getUrl获取也是一种性能损耗。
解决方案: 修改缓存key。实际上数据库方言在应用整个运行过程中是不变的,那么只要将DataSource
实例对象做为缓存可以,就可以避免重复调用getUrl方法。代码如下:
private AbstractHelperDialect getDialect(MappedStatement ms) {
//改为对dataSource做缓存
DataSource dataSource = ms.getConfiguration().getEnvironment().getDataSource();
AbstractHelperDialect helperDialect = urlDialectMap.get(dataSource);
if (helperDialect != null) {
return helperDialect;
}
try {
lock.lock();
helperDialect = urlDialectMap.get(dataSource);
if (helperDialect != null) {
return helperDialect;
}
String url = getUrl(dataSource);
if (StringUtil.isEmpty(url)) {
throw new PageException("无法自动获取jdbcUrl,请在分页插件中配置dialect参数!");
}
String dialectStr = fromJdbcUrl(url);
if (dialectStr == null) {
throw new PageException("无法自动获取数据库类型,请通过 helperDialect 参数指定!");
}
AbstractHelperDialect dialect = initDialect(dialectStr, properties);
urlDialectMap.put(dataSource, dialect);
return dialect;
} finally {
lock.unlock();
}
}
总结: 然而这种解决方案也存在一个问题,因为DataSource
是一个接口,并不知道实现类会如何重写hashCode
和equals
方法。当系统中存在多数据源时,可能出现value值被替换的情况。当然这种是hashCode
和equals
重写不合理才会导致的情况,知道可能存在这种情况就好。