后端服务故障排查 -- 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 高负载排查

排查相关命令

1. top 查找耗CPU的进程
2. ps -ef|grep pid 查看进程信息
3. top -H -p pid 查看指定进程下的线程情况，找到耗cpu的进程 (当前耗cpu，以及总耗时)
4. 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