后端服务故障排查 -- dubbo服务超时、线程池耗尽 CPU高负载
转载：https://blog.csdn.net/LG772EF/article/details/90341248?spm=1001.2101.3001.6650.11&utm_medium=distribute.pc_relevant.none-task-blog-2%7Edefault%7EBlogCommendFromBaidu%7ERate-11-90341248-blog-115986471.235%5Ev27%5Epc_relevant_recovery_v2&depth_1-utm_source=distribute.pc_relevant.none-task-blog-2%7Edefault%7EBlogCommendFromBaidu%7ERate-11-90341248-blog-115986471.235%5Ev27%5Epc_relevant_recovery_v2&utm_relevant_index=12
问题现象
dubbo线程池耗尽的异常日志
cpu占用情况
问题排查
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)
线程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)
再次抓了一次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资源
调整后验证
基于上面分析的情况，屏蔽的sql插件 (暂没有想到如何更好的拼接完整sql，和同一次请求的业务日志一起输出)。
再次验证2w条导入。
ps: sql插件后面启用了，目前改成异步输出sql了
总体CPU占用情况
CPU占用线程分析
8776(0x2248) stack trace
"DubboServerHandler-172.16.7.77:20882-thread-139" #1565 daemon prio=5 os_prio=0 tid=0x00007fd64402a000 nid=0x2248 runnable [0x00007fd534d16000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174)
- locked <0x00000006d4a39ee0> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2494)
- locked <0x00000006d4a2ef48> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
- locked <0x00000006d4a2ef48> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
- locked <0x00000006d4a2ef48> (a com.mysql.jdbc.JDBC4Connection)
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3051)
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:440)
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3049)
at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:168)
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:494)
at sun.reflect.GeneratedMethodAccessor176.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.logging.jdbc.PreparedStatementLogger.invoke(PreparedStatementLogger.java:59)
at com.sun.proxy.$Proxy167.execute(Unknown Source)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:185)
at sun.reflect.GeneratedMethodAccessor1155.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.$Proxy68.insert(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.insert(SqlSessionTemplate.java:278)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:57)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy71.insertList(Unknown Source)
at sun.reflect.GeneratedMethodAccessor1898.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.insertListThrow(BaseManagerImpl.java:219)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeRelationManagerImpl.insertList(CmAttributeRelationManagerImpl.java:474)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.CmAttributeRelationManagerImpl$$FastClassBySpringCGLIB$$b030c03c.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.transaction.interceptor.TransactionInterceptor$$Lambda$23/1344266818.proceedWithInvocation(Unknown Source)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:288)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
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.CmAttributeRelationManagerImpl$$EnhancerBySpringCGLIB$$11d3e1ef.insertList(<generated>)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl$SaveOrUpdate.save(GoodsManagerImpl.java:869)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl$SaveOrUpdate.access$300(GoodsManagerImpl.java:666)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl.saveAll(GoodsManagerImpl.java:163)
at com.wwwarehouse.xdw.resourcecenter.manager.impl.goods.GoodsManagerImpl$$FastClassBySpringCGLIB$$a08911ec.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.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:52)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
at org.springframework.transaction.interceptor.TransactionInterceptor$$Lambda$23/1344266818.proceedWithInvocation(Unknown Source)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:288)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
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.goods.GoodsManagerImpl$$EnhancerBySpringCGLIB$$e3794618.saveAll(<generated>)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl.importGoods(GoodsServiceImpl.java:94)
at com.wwwarehouse.xdw.resourcecenter.service.impl.rs.goods.GoodsServiceImpl$$FastClassBySpringCGLIB$$98204a1f.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.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85)
at com.wwwarehouse.xdw.resourcecenter.aspect.ResourceScrutineer.doLogHandle(ResourceScrutineer.java:80)
at sun.reflect.GeneratedMethodAccessor319.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
at com.alibaba.druid.support.spring.stat.DruidStatInterceptor.invoke(DruidStatInterceptor.java:72)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
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.service.impl.rs.goods.GoodsServiceImpl$$EnhancerBySpringCGLIB$$b1d03b86.importGoods(<generated>)
at com.alibaba.dubbo.common.bytecode.Wrapper93.invokeMethod(Wrapper93.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:74)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.wwwarehouse.commons.dubbo.DubboProviderAuthFilter.invoke(DubboProviderAuthFilter.java:41)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:133)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
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)
其他执行的一些优化点
简单遍历、计算串行化
一些纯遍历、计算的逻辑，由线程池并行改为串行。逻辑比较简单，由于线程切换开销，对单次服务响应而言，耗时估计不会缩短。总体服务的响应时间变长了。
日志输出优化
日志只输出到日志文件，关闭console输出。切面服务拦截时，控制日志输出的最大长度等
参考资料
CPU 占用排查分析：https://cloud.tencent.com/developer/article/1377496
显示CPU高占用的命令：https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#beer-show-busy-java-threadssh
————————————————
版权声明：本文为CSDN博主「【随风飘流】」的原创文章，遵循CC 4.0 BY-SA版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/LG772EF/article/details/90341248
