只改了5行代码，接口吞吐量提升了10多倍这两天来了一个“大客户”，对并发量提出了要求：核心接口的吞吐量和几个关键的使用单节点场景最低要求500/s。当时想想，500/s的吞吐量也不容易。Tomcat使用100个线程，即1S内单线程处理5个请求，200ms内处理1个请求。这没有问题。界面响应时间大多在100ms左右，不是每分钟都能满足的。但是开始压测的时候，100并发时吞吐量只有50%。。。又查了一下，100并发时CPU占用接近80%。。。从上图中可以看到几个重要的信息.最小值：表示在我们的非并发场景下，单个接口响应的时长。小于100毫秒。非常好！最大值：在并发场景下，由于各种锁或者其他串行操作，导致部分请求等待时间增加，接口整体响应时间变长。5秒。有点过分了！！！再看百分位数，大部分请求响应时间都在4s以内。无语！！！所以单节点1s的吞吐量只有50。比500还差10倍。难受！！！！分析过程定位“慢”的原因。暂时忽略CPU占用率高的问题。第一，平均响应时间这么慢，肯定是被屏蔽了。先确定阻塞位置。重点排查几个点：锁（同步锁、分布式锁、数据库锁）耗时操作（链接耗时、SQL耗时）结合这些先配置耗时埋点。接口响应时间统计。超过500ms则打印告警日志。接口内部远程调用的耗时统计。200ms打印告警日志。Redis访问需要时间。超过10ms打印告警日志。SQL执行需要时间。超过100ms则打印告警日志。以上配置生效后，通过日志排查发现接口上存在慢SQL。具体的SQL类似这样：updatetablesetfield=field-1wheretype=1andfiled>1;复制代码上面的SQL相当于并发操作同一条数据，肯定有锁在等待。日志显示这里的等待时间占整个接口时间的80%以上。话不多说，先改成尊重。因为是压测环境，所以直接改成异步执行，确认一下效果。PS：我当时心里是这么想的：完了，你完了。这就是问题所在！悬崖就是原因！只是优化它。当然，如果这么简单，这篇文章就不用写了……优化效果：嗯……嗯……好！这个优化还是很明显的，提升了将近2倍。这个时候已经觉得不对劲了，慢SQL已经解决了（异步~随便~你执行10s我不管），虽然吞吐量的提升没有预期的效果。但数字不会说谎。最大值：已经从5s->2s百分位值：4s->1s这已经是很大的进步了。继续定位“慢”的原因通过第一阶段的“优化”，我们离目标又近了很多。废话不多说，继续下一步的调查。我们继续看日志。此时日志类似如下：2023-01-0415:17:05:347INFO....50[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:348INFO。...21[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:350信息....47[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:465信息....234[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:467信息....123[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:581信息....451[TID:1s22s72s8ws9w00]*2023-01-0415:17:05:702INFO....72[TID:1s22s72s8ws9w00]*小间隔复制前三行info日志没有问题。第4~5、6~7、7~8显然有几百毫秒的耗时。查看代码发现这部分没有耗时的操作。那么这段时间你都在做什么呢？发生线程切换，切换另一个线程执行其他任务。(Toomanythreads)打印日志太多，压测5分钟日志量500M。（记住日志打印太多影响很大）STW。（但是日志还在输出，所以前两种可能性很高，一般不会有100毫秒停顿。）根据这三个思路，做了如下操作：首先，将日志打印级别提高到调试。emm...提升不大，好像增加了10左右。然后，去掉线程@Async注解，使用线程池控制代码线程池数量（之前有3个线程池，现在统一配置的核心线程数为100）。结合业务，服务核心线程总数控制在50以内，同步增加最大阻塞大小。结果还不错，增加了50，接近200。最后观察JVM的GC日志，发现YGC的频率是4/s，没有FGC。1分钟内的GC时间不到1s，明显不是GC问题，但是发现JVM内存太小，只有512M，直接分配到4G。吞吐量并没有太大的提升，YGC的频率降低到2秒一次。唉，操作猛如虎。PS：其实中间就是在乱搞数据库参数，这里就不多说了。其实也不是没有收获，至少在减少了服务线程数之后，还是有一些收获的。另外，还有一点一直在关注：CPU使用率。减少线程数后，CPU使用率并没有明显下降。之前线程多，CPU占用率高是可以理解的。但是，剪掉了大半的线头之后，还是很奇怪。这时，关注的焦点开始从代码“慢”的方向转移到“CPU高”的方向。定位CPU占用率高的原因。CPU使用率高通常与线程数有关。一定没有问题。到时候，高级别的原因可能有以下两个考虑：有额外的线程。该代码有一些CPU密集型操作。然后继续操作：观察服务的活跃线程数。检查CPU使用率高的线程。观察过程中，发现并没有明显的CPU占用率高的线程。所有线程基本都在10%以内。类似于下图，但有很多线程。如果不是很高，就证明大家都正常，就是太多了……此时，也没有再探查的想法了。当时想，算了，打印栈看看，看看自己做了什么~在看的过程中发现了这条日志："http-nio-6071-exec-9"#82daemonprio=5os_prio=0tid=0x00007fea9aed1000nid=0x62可运行[0x00007fe934cf4000]java.lang.Thread.State:RUNNABLEatorg.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1058)atorg.springvisframeworkJAdaoptexiontexpanJ.Anspectory(AbstractAspectJAdvisorFactory.java:216)在org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.(AbstractAspectJAdvisorFactory.java:197)在org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.jaAspectFactory.findAnnotation.AbstractAspectJAdvisorFactory.java:197:147)在org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(AbstractAspectJAdvisorFactory.java:135)在org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvice(ReflectiveAspectJAdvisorF)actory.java:244）在org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.instantiateAdvice（InstantiationModelAwarePointcutAdvisorImpl.java:149）在org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.（InstantiationModelAwarePointcutAdvisorImpl.java:149）在org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisor（ReflectiveAspectJAdvisorFactory.java:213）在org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisors（ReflectiveAspectJAdvisorFactory.java:144）在org.springaspect.annotation.BeanFactoryAspectJAdvisorsBuilder.buildAspectJAdvisors(BeanFactoryAspectJAdvisorsBuilder.java:149)atorg.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator.findCandidateAdvisors(AnnotationAwareAspectJAutoProxyCreator.java:95)atorg.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.shouldSkip(AspectJAwareAdvisorAutoProxyCreator.java:101)atorg.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:333)atorg.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:291）在org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization（AbstractAutowireCapableBeanFactory.java:455）在org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean（AbstractAutowireCapableBeanFactory8.java:1.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean（AbstractAutowireCapableBeanFactory.java:620）在org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean（AbstractAutowireCapableBeanFactory.java:542）在org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean（AbstractBeanFactory.java:353）在org.springframework.beans.factory.support.AbstractBeanFactory.getBean（AbstractBeanFactory.java:233）在org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean（DefaultListable.javaBeanFactory1282）在org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean（DefaultListableBeanFactory.java:1243）在org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveBean（DefaultListableBeanFactory.java:494）在org.factory.support。DefaultListableBeanFactory.getBean（DefaultListableBeanFactory.java:349）在org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean（DefaultListableBeanFactory.java:342）在cn.hutool.extra.spring.SpringUtil.getBean（SpringUtil.java:117）............复制栈上面的代码，发现一个点：在执行getBean的时候，执行的是createBean方法。我们都知道Spring管理的bean都是预先实例化后放在IOC容器中的。createBean要做的事情很多，比如Bean初始化，其他类的依赖注入，中间还有一些前处理器和后处理器的执行，代理检查等，是一个比较耗时的方法，所以程序启动时扫描，加载，并完成Bean的初始化。而我们在运行的程序线程栈中发现了这个操作。并且通过搜索，发现有将近200个地方。通过堆栈信息快速定位执行位置：RedisToolredisTool=BeanUtils.getBean(RedisMaster.class);复制代码和RedisMasterclass@Component@Scope("prototype")publicclassRedisMasterimplementsIRedisTool{//。.....}复制代码是的，它使用了多个示例。而且使用的地方是Redis（系统使用Jedis客户端，Jedis不是线程安全的，每次使用都需要一个新的实例），接口使用Redis相当频繁，一个接口需要获取Redis数据约10倍。这意味着执行createBean逻辑大约10次……唉！！！赶紧改代码，直接用万能的new。在看结果之前，还有一点需要提一下，因为系统有很多统计和耗时的操作。实现方法是通过：longstart=System.currentTimeMillis();//......longend=System.currentTimeMillis();longrunTime=start-end;复制代码或者Hutool提供的StopWatch：这里感谢huoger根据同学的意见，我误以为这种方法可以降低对性能的影响，其实只是一层封装。在幕后，使用了System.nanoTime()。StopWatchwatch=newStopWatch();watch.start();//......watch.stop();System.out.println(watch.getTotalTimeMillis());copycode并且这个在并发度很高的情况下，对性能的影响还是比较大的，尤其是当server使用了一些特定的clocks的时候。这里不多说，感兴趣的可以自行搜索。最终结果：调查涉及的命令如下：查询服务进程的CPU状态：top–Hppid查询JVMGC相关参数：jstat-gcpid2000(forpid[processnumber]每隔2s输出一条log)打印当前栈信息：jstack-lpid>>stack.log总结结果不错，过程曲折。总的来说，知识还是有欠缺的。文章看似顺风顺水，其实都是事后诸葛亮。不，应该是鞋匠。基本上就是查资料，分析，操作。前后历时4天，尝试了很多。Mysql：BufferPool、ChangeBuffer、RedoLog大小、双一配置...代码：异步执行、线程池参数调整、tomcat配置、Druid连接池配置...JVM：内存大小、分配、垃圾收集器都想要改...都是乱七八糟的，能想到的都试试。后续要多学习性能优化，至少要对故障排查思路清晰，不要乱来。
