后端服务故障排查 -- dubbo服务超时、线程池耗尽 CPU高负载
文章目录
问题现象
5-6 到 5-7，某测试环境我们的服务时常收到调用方反馈，dubbo接口超时。
查看后台的错误日志信息，以及环境监控情况。
有两个问题，一是dubbo服务通道关闭，线程池耗尽了。调用方表现为服务超时。二是CPU使用有点异常，某些时段占用很高。
dubbo线程池耗尽的异常日志
[DUBBO] An exception was thrown by a user handler while handling an exception event ([id: 0xa7e4b981, /172.16.*.*:4216 :> /172.16.*.*:20882] EXCEPTION: java.nio.channels.ClosedChannelException),
dubbo version: resourcecenter, current host: 172.16.*.* com.alibaba.dubbo.remoting.ExecutionException: class com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler error when process caught event .
at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:67) ~[resourcecenter.jar:?]
at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44) ~[resourcecenter.jar:?]
at com.alibaba.dubbo.remoting.transport.AbstractChannelHandlerDelegate.caught(AbstractChannelHandlerDelegate.java:44) ~[resourcecenter.jar:?]
...
Caused by: java.util.concurrent.RejectedExecutionException: Thread pool is EXHAUSTED!
Thread Name: DubboServerHandler-172.16.*.*:20882, Pool Size: 200 (active: 185, core: 200, max: 200, largest: 200), Task: 1341173 (completed: 1340996),
Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://172.16.*.*:20882!
at com.alibaba.dubbo.common.threadpool.support.AbortPolicyWithReport.rejectedExecution(AbortPolicyWithReport.java:53) ~[resourcecenter.jar:?]
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823) ~[?:1.8.0_111]
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369) ~[?:1.8.0_111]
at com.alibaba.dubbo.remoting.transport.dispatcher.all.AllChannelHandler.caught(AllChannelHandler.java:65) ~[resourcecenter.jar:?]
...
cpu占用情况
2天总览
05-07, 某一个时段
问题排查
dubbo线程池耗尽排查
根据异常，网上搜索到了相同的现象以及解决方案。
解决方案：
修改dubbo provider的dispatcher策略，设置为message
<dubbo:protocol name=“dubbo” port=“8888” threads=“500” dispatcher=“message” />
dispatcher默认为all，所有的请求，均会分发给业务线程池处理。
dubbo默认的业务线程池大小是200，等待队列长度为0，
当线程池全部满了之后，后续的请求会丢弃。
但丢弃的请求也会交给业务线程池处理，
此时可能出现服务端已拒绝，但consumer一直在等待，直到超时
dubbo Provider线程池exhausted分析：https://www.jianshu.com/p/99ca76a48882
dubbo线程模型：https://www.cnblogs.com/java-zhao/p/7822766.html
dubbo的线程模型和线程池策略：http://c45c43d4.wiz03.com/share/s/34n4fk0NQkwU2orqij3DPijj0qYiG005xkpg2fH7CT2lWKq1
cpu 高负载排查
排查相关命令
top 查找耗CPU的进程
ps -ef|grep pid 查看进程信息
top -H -p pid 查看指定进程下的线程情况，找到耗cpu的进程 (当前耗cpu，以及总耗时)
jstack pid 生成指定经常的堆栈跟踪信息
tip: 第三步查看到进程下的线程信息，线程id是10进制的。需要转成16进制的。jstack里面的线程id是16进制的
排查
初步定位问题场景
观察CPU的占用情况，某一时刻，发现cpu占用有所提高，查看了一下耗费cpu的线程，这个代码对应的是商品导入业务。怀疑是该业务引起的。
观察到的时间和通过命令获取到stack的时间有1-2s差异。cpu占用的时候，是runnable状态，此时已经是waiting状态了。
验证，确认问题点
针对上述怀疑的业务审商品导入，多次执行该业务，发现进行大量数据导入的时候CPU占用飙升。
和测试同学确认了下，这两天在对该功能进行大数据量导入验证。
– 每次导入的时候，耗时也很久(1W条)
自己进行测试，导入2w条商品，CPU占用情况如下：
2019-05-08 这几个线程，单核CPU都99%左右。20319(0x4F5F) ，20320(0x4F60) ，20608(0x5080)
stack trace信息如下
线程0x4F5F的栈轨迹
"warehouse-thread-15" #4240 prio=5 os_prio=0 tid=0x00007f0e101d7800 nid=0x4f5f runnable [0x00007f0d30047000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$Start.match(Pattern.java:3461)
at java.util.regex.Matcher.search(Matcher.java:1248)
at java.util.regex.Matcher.find(Matcher.java:637)
at java.util.regex.Matcher.replaceFirst(Matcher.java:1001)
at java.lang.String.replaceFirst(String.java:2178)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.showSql(MybatisInterceptorUtil.java:130)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.getSql(MybatisInterceptorUtil.java:78)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.intercept(MybatisInterceptorUtil.java:54)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy164.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy70.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:137)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:75)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy89.selectByExample(Unknown Source)
at sun.reflect.GeneratedMethodAccessor599.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExampleThrow(BaseManagerImpl.java:287)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExample(BaseManagerImpl.java:297)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listByIdentifyCodes(CmIdentifyRelationManagerImpl.java:140)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listFirstByIdentifyCodes(CmIdentifyRelationManagerImpl.java:148)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$FastClassBySpringCGLIB$$eb82d39e.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$EnhancerBySpringCGLIB$$4ccbb66b.listFirstByIdentifyCodes(<generated>)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.getCodeRelation(GoodsServiceImpl.java:390)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.lambda$fillUkidIfPresnetForSpu$4(GoodsServiceImpl.java:216)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl$$Lambda$79/1577360053.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
线程4F60的栈轨迹
"warehouse-thread-16" #4241 prio=5 os_prio=0 tid=0x00007f0e101d8800 nid=0x4f60 runnable [0x00007f0d30088000]
java.lang.Thread.State: RUNNABLE
at java.lang.StringBuffer.append(StringBuffer.java:338)
- locked <0x0000000758ece3c0> (a java.lang.StringBuffer)
at java.util.regex.Matcher.appendReplacement(Matcher.java:890)
at java.util.regex.Matcher.replaceFirst(Matcher.java:1004)
at java.lang.String.replaceFirst(String.java:2178)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.showSql(MybatisInterceptorUtil.java:130)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.getSql(MybatisInterceptorUtil.java:78)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.intercept(MybatisInterceptorUtil.java:54)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy164.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy70.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:137)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:75)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy89.selectByExample(Unknown Source)
at sun.reflect.GeneratedMethodAccessor599.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExampleThrow(BaseManagerImpl.java:287)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExample(BaseManagerImpl.java:297)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listByIdentifyCodes(CmIdentifyRelationManagerImpl.java:140)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listFirstByIdentifyCodes(CmIdentifyRelationManagerImpl.java:148)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$FastClassBySpringCGLIB$$eb82d39e.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$EnhancerBySpringCGLIB$$4ccbb66b.listFirstByIdentifyCodes(<generated>)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.getCodeRelation(GoodsServiceImpl.java:390)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.lambda$fillUkidIfPresnetForSpu$3(GoodsServiceImpl.java:213)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl$$Lambda$78/959775108.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
线程5080的栈轨迹
"warehouse-thread-37" #4398 prio=5 os_prio=0 tid=0x00007f0e1042f000 nid=0x5080 runnable [0x00007f0d232ee000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3797)
at java.util.regex.Pattern$Start.match(Pattern.java:3461)
at java.util.regex.Matcher.search(Matcher.java:1248)
at java.util.regex.Matcher.find(Matcher.java:637)
at java.util.regex.Matcher.replaceFirst(Matcher.java:1001)
at java.lang.String.replaceFirst(String.java:2178)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.showSql(MybatisInterceptorUtil.java:130)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.getSql(MybatisInterceptorUtil.java:78)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.intercept(MybatisInterceptorUtil.java:54)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy164.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy70.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:137)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:75)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy89.selectByExample(Unknown Source)
at sun.reflect.GeneratedMethodAccessor599.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExampleThrow(BaseManagerImpl.java:287)
at com.wwwarehouse.commons.mybatis.BaseManagerImpl.selectByExample(BaseManagerImpl.java:297)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listByIdentifyCodes(CmIdentifyRelationManagerImpl.java:140)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl.listFirstByIdentifyCodes(CmIdentifyRelationManagerImpl.java:148)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$FastClassBySpringCGLIB$$eb82d39e.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmIdentifyRelationManagerImpl$$EnhancerBySpringCGLIB$$4ccbb66b.listFirstByIdentifyCodes(<generated>)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.getCodeRelation(GoodsServiceImpl.java:390)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.lambda$fillUkidIfPresnetForSpu$5(GoodsServiceImpl.java:224)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl$$Lambda$80/1844666599.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
再次抓了一次stack，另外一个耗费cpu(90%+)的线程（0x50a）
"warehouse-thread-50" #4412 prio=5 os_prio=0 tid=0x00007f0e10268000 nid=0x50a7 runnable [0x00007f0d22b91000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3797)
at java.util.regex.Pattern$Start.match(Pattern.java:3461)
at java.util.regex.Matcher.search(Matcher.java:1248)
at java.util.regex.Matcher.find(Matcher.java:637)
at java.util.regex.Matcher.replaceFirst(Matcher.java:1001)
at java.lang.String.replaceFirst(String.java:2178)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.showSql(MybatisInterceptorUtil.java:130)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.getSql(MybatisInterceptorUtil.java:78)
at com.wwwarehouse.commons.mybatis.utils.MybatisInterceptorUtil.intercept(MybatisInterceptorUtil.java:54)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy164.query(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
at sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy70.selectList(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:230)
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:137)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:75)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy71.selectByExample(Unknown Source)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeManagerImpl.listByAttributeNames(CmAttributeManagerImpl.java:113)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeManagerImpl.saveAttributesIfAbsent(CmAttributeManagerImpl.java:229)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeManagerImpl.listUkidByNames(CmAttributeManagerImpl.java:213)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeManagerImpl$$FastClassBySpringCGLIB$$36b282d8.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeManagerImpl$$EnhancerBySpringCGLIB$$e75d1859.listUkidByNames(<generated>)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl$SaveOrUpdate.lambda$save$5(GoodsManagerImpl.java:696)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl$SaveOrUpdate$$Lambda$548/1831869395.call(Unknown Source)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
原因分析
以上几次占轨迹，均指向MybatisInterceptorUtil.showSql这个方法里面涉及到的正则使用
这个是我们自身实现的Mybastic sql拦截，将完整的sql打印出来。
代码如下，主要逻辑是组装完整sql，将占位符替换为真正的参数输出。
商品导入业务，涉及大量通过条码or名称查找对象的，一次几w条(测试随机生成的数据，条码内容不一样)，会执行大量的String.replaceFirst操作。这个是遍历、正则匹配、替换等操作，需要消耗CPU资源
public static String showSql(Configuration configuration, BoundSql boundSql) {
Object parameterObject = boundSql.getParameterObject();
List<ParameterMapping> parameterMappings = boundSql
.getParameterMappings();
String sql = boundSql.getSql().replaceAll("[\\s]+", " ");
if (CollectionUtils.isNotEmpty(parameterMappings) && parameterObject != null) {
TypeHandlerRegistry typeHandlerRegistry = configuration
.getTypeHandlerRegistry();
if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
sql = sql.replaceFirst("\\?",
Matcher.quoteReplacement(getParameterValue(parameterObject)));
} else {
MetaObject metaObject = configuration
.newMetaObject(parameterObject);
for (ParameterMapping parameterMapping : parameterMappings) {
String propertyName = parameterMapping.getProperty();
if (metaObject.hasGetter(propertyName)) {
Object obj = metaObject.getValue(propertyName);
sql = sql.replaceFirst("\\?", Matcher.quoteReplacement(getParameterValue(obj)));
} else if (boundSql.hasAdditionalParameter(propertyName)) {
Object obj = boundSql
.getAdditionalParameter(propertyName);
sql = sql.replaceFirst("\\?", Matcher.quoteReplacement(getParameterValue(obj)));
} else {
sql = sql.replaceFirst("\\?", "缺失");
}//打印出缺失，提醒该参数缺失并防止错位
}
}
}
return sql;
}
自己本机验证了一下，根据条码找商品，加sql拦截和不加sql拦截的情况。
没有sql打印插件
参数数量: 20000, 耗时(ms):1615
参数数量: 20000, 耗时(ms):1733
有sql打印插件
参数数量: 20000, 耗时(ms):19681
参数数量: 20000, 耗时(ms):23706
有SQL打印的情况下，会长时间占用CPU资源
其他执行的一些优化点
简单遍历、计算串行化
一些纯遍历、计算的逻辑，由线程池并行改为串行。逻辑比较简单，由于线程切换开销，对单次服务响应而言，耗时估计不会缩短。总体服务的响应时间变长了。
日志输出优化
日志只输出到日志文件，关闭console输出。切面服务拦截时，控制日志输出的最大长度等
————————————————