我只改五行代码，接口性能提升了 10 倍！

背景

某公司的一个 ToB 系统，因为客户使用的也不多，没啥并发要求，就一直没有经过压测。这两天来了一个“大客户”，对并发量提出了要求：核心接口与几个重点使用场景单节点吞吐量要满足最低500/s的要求。

当时一想，500/s吞吐量还不简单。Tomcat按照 100 个线程，那就是单线程 1S 内处理 5 个请求，200ms 处理一个请求即可。这个没有问题，平时接口响应时间大部分都 100ms 左右，还不是分分钟满足的事情。然而压测一开，100 的并发，吞吐量居然只有 50 ...

而且再一查，100 的并发，CPU 使用率居然接近 80% ...

从上图可以看到几个重要的信息：

最小值：表示我们非并发场景单次接口响应时长。还不足100ms。挺好!
最大值：并发场景下，由于各种锁或者其他串行操作，导致部分请求等待时长增加，接口整体响应时间变长。5秒钟。有点过分了！！！
再一看百分位，大部分的请求响应时间都在4s。无语了！！！

所以 1s 钟的吞吐量单节点只有 50 。距离 500 差了 10 倍。难受！！！！

分析过程

定位“慢”原因

这里暂时先忽略 CPU 占用率高的问题

首先平均响应时间这么慢，肯定是有阻塞。先确定阻塞位置。重点检查几处：

锁 (同步锁、分布式锁、数据库锁)
耗时操作 (链接耗时、SQL耗时)

结合这些先配置耗时埋点。

接口响应时长统计。超过 500ms 打印告警日志。
接口内部远程调用耗时统计。200ms 打印告警日志。
Redis 访问耗时。超过 10ms 打印告警日志。
SQL 执行耗时。超过 100ms 打印告警日志。

上述配置生效后，通过日志排查到接口存在慢SQL。具体SQL类似与这种：

<!-- 主要类似与库存扣减 每次-1 type 只有有限的几种且该表一共就几条数据（一种一条记录）-->
<!-- 压测时可以认为 type = 1 是写死的 -->
update table set field = field - 1 where type = 1 and filed > 1;

上述 SQL 相当于并发操作同一条数据，肯定存在锁等待。日志显示此处的等待耗时占接口总耗时 80% 以上。

二话不说先改为敬。因为是压测环境，直接改为异步执行，确认一下效果。

PS：当时心里是这么想的：妥了，大功告成。就是这里的问题！绝壁是这个原因！优化一下就解决了。当然，如果这么简单就没有必要写这篇文章了...

优化后的效果：

嗯... emm... 好！这个优化还是很明显的，提升提升了近 2 倍。

此时已经感觉到有些不对了，慢 SQL 已经解决了（异步了~ 随便吧~ 你执行 10s 我也不管了），虽然对吞吐量的提升没有预期的效果。但是数据是不会骗人的。

最大值：已经从 5s -> 2s
百分位值：4s -> 1s

这已经是很大的提升了。

继续定位“慢”的原因

通过第一阶段的“优化”，我们距离目标近了很多。废话不多说，继续下一步的排查。

我们继续看日志，此时日志出现类似下边这种情况：

2023-01-04 15:17:05:347 INFO **.**.**.***.50 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:348 INFO **.**.**.***.21 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:350 INFO **.**.**.***.47 [TID: 1s22s72s8ws9w00] **********************

2023-01-04 15:17:05:465 INFO **.**.**.***.234 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:467 INFO **.**.**.***.123 [TID: 1s22s72s8ws9w00] **********************

2023-01-04 15:17:05:581 INFO **.**.**.***.451 [TID: 1s22s72s8ws9w00] **********************

2023-01-04 15:17:05:702 INFO **.**.**.***.72 [TID: 1s22s72s8ws9w00] **********************

前三行 info 日志没有问题，间隔很小。第 4 ~ 第 5，第 6 ~ 第 7，第 7 ~ 第 8 很明显有百毫秒的耗时。检查代码发现，这部分没有任何耗时操作。那么这段时间干什么了呢？

发生了线程切换，换其他线程执行其他任务了。(线程太多了)
日志打印太多了，压测5分钟日志量500M。（记得日志打印太多是有很大影响的）
STW。（但是日志还在输出，所以前两种可能性很高，而且一般不会停顿百毫秒）

按照这三个思路做了以下操作：

首先，提升日志打印级别到 DEBUG。emm... 提升不大，好像增加了 10 左右。
然后，拆线程 @Async 注解使用线程池，控制代码线程池数量（之前存在3个线程池，统一配置的核心线程数为100）结合业务，服务总核心线程数控制在 50 以内，同步增加阻塞最大大小。结果还可以，提升了 50，接近 200 了。
最后，观察 JVM 的 GC 日志，发现 YGC 频次4/s，没有 FGC。1 分钟内 GC 时间不到 1s，很明显不是 GC 问题，不过发现JVM内存太小只有 512M，直接给了 4G。吞吐量没啥提升，YGC频次降低为 2 秒 1 次。

唉，一顿操作猛如虎。

PS：其实中间还对数据库参数一通瞎搞，这里不多说了。

其实也不是没有收获，至少在减少服务线程数量后还是有一定收获的。另外，已经关注到了另外一个点：CPU 使用率，减少了线程数量后，CPU 的使用率并没有明显的下降，这里是很有问题的，当时认为 CPU 的使用率主要与开启的线程数量有关，之前线程多，CPU 使用率较高可以理解。但是，在砍掉了一大半的线程后，依然居高不下这就很奇怪了。

此时关注的重点开始从代码“慢”方向转移到“CPU高”方向。

定位 CPU 使用率高的原因

CPU 的使用率高，通常与线程数相关肯定是没有问题的。当时对居高不下的原因考虑可能有以下两点：

有额外的线程存在。
代码有部分 CPU 密集操作。

然后继续一顿操作：

观察服务活跃线程数。
观察有无 CPU 占用率较高线程。

在观察过程中发现，没有明显 CPU 占用较高线程。所有线程基本都在 10% 以内。类似于下图，不过有很多线程。

没有很高就证明大家都很正常，只是多而已...

此时没有下一步的排查思路了。当时想着,算了打印一下堆栈看看吧，看看到底干了啥~

在看的过程中发现这段日志：

"http-nio-6071-exec-9" #82 daemon prio=5 os_prio=0 tid=0x00007fea9aed1000 nid=0x62 runnable [0x00007fe934cf4000]
   java.lang.Thread.State: RUNNABLE
 at org.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1058)
 at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.resolveExpression(AbstractAspectJAdvisorFactory.java:216)
 at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.<init>(AbstractAspectJAdvisorFactory.java:197)
 at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAnnotation(AbstractAspectJAdvisorFactory.java:147)
 at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(AbstractAspectJAdvisorFactory.java:135)
 at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvice(ReflectiveAspectJAdvisorFactory.java:244)
 at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.instantiateAdvice(InstantiationModelAwarePointcutAdvisorImpl.java:149)
 at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.<init>(InstantiationModelAwarePointcutAdvisorImpl.java:113)
 at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisor(ReflectiveAspectJAdvisorFactory.java:213)
 at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisors(ReflectiveAspectJAdvisorFactory.java:144)
 at org.springframework.aop.aspectj.annotation.BeanFactoryAspectJAdvisorsBuilder.buildAspectJAdvisors(BeanFactoryAspectJAdvisorsBuilder.java:149)
 at org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator.findCandidateAdvisors(AnnotationAwareAspectJAutoProxyCreator.java:95)
 at org.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.shouldSkip(AspectJAwareAdvisorAutoProxyCreator.java:101)
 at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:333)
 at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:291)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization(AbstractAutowireCapableBeanFactory.java:455)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1808)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
 at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:353)
 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:233)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1282)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1243)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveBean(DefaultListableBeanFactory.java:494)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:349)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:342)
 at cn.hutool.extra.spring.SpringUtil.getBean(SpringUtil.java:117)
        ......  
        ......

上边的堆栈发现了一个点：在执行 getBean 的时候，执行了 createBean 方法。我们都知道 Spring 托管的 Bean 都是提前实例化好放在 IOC 容器中的。createBean 要做的事情有很多，比如 Bean 的初始化，依赖注入其他类，而且中间还有一些前后置处理器执行、代理检查等等，总之是一个耗时方法，所以都是在程序启动时去扫描，加载，完成 Bean 的初始化。

而我们在运行程序线程堆栈中发现了这个操作。而且通过检索发现竟然有近 200 处。

通过堆栈信息很快定位到执行位置：

<!--BeanUtils 是 hutool 工具类。也是从IOC容器获取Bean 等价于 @Autowired 注解 -->
RedisTool redisTool = BeanUtils.getBean(RedisMaster.class);

而RedisMaster类

@Component
@Scope("prototype")
public class RedisMaster implements IRedisTool {
    // ......
}

没错就是用了多例。而且使用的地方是 Redis（系统使用 Jedis 客户端，Jedis 并非线程安全，每次使用都需要新的实例），接口对 Redis 的使用还是比较频繁的，一个接口得有 10 次左右获取 Redis 数据。也就是说执行 10 次左右的 createBean 逻辑 ...

叹气！！

赶紧改代码，直接使用万能的 new。

在看结果之前还有一点需要提一下，由于系统有大量统计耗时的操作。实现方式是通过：

long start = System.currentTimeMillis();
// ......
long end = System.currentTimeMillis();
long runTime = start - end;

或者 Hutool 提供的 StopWatch：

当时还误以为该方式能够降低性能的影响，但是实际上也只是一层封装。底层使用的是 System.nanoTime()。

StopWatch watch = new StopWatch();
watch.start();
// ......
watch.stop();
System.out.println(watch.getTotalTimeMillis());

而这种在并发量高的情况下，对性能影响还是比较大的，特别在服务器使用了一些特定时钟的情况下。这里就不多说，感兴趣的可以自行搜索一下。

最终结果：

排查涉及的命令如下：

查询服务进程CPU情况：top –Hp pid
查询JVM GC相关参数：jstat -gc pid 2000 (对 pid [进程号] 每隔 2s 输出一次日志)
打印当前堆栈信息：jstack -l pid >> stack.log

总结

结果是好的，过程是曲折的。总的来说还是知识的欠缺，文章看起来还算顺畅，但都是事后诸葛亮，不对，应该是时候臭皮匠。基本都是边查资料边分析边操作，前后花费了4天时间，尝试了很多。

Mysql : Buffer Pool 、Change Buffer 、Redo Log 大小、双一配置...
代码 : 异步执行，线程池参数调整，tomcat 配置，Druid连接池配置...
JVM : 内存大小，分配，垃圾收集器都想换...

总归一通瞎搞，能想到的都试试。后续还需要多了解一些性能优化知识，至少要做到排查思路清晰，不瞎搞。

最后5行代码有哪些：

new Redis实例：1 耗时统计：3 SQL异步执行 @Async：1（上图最终的结果是包含该部分的，时间原因未对SQL进行处理，后续会考虑Redis原子操作+定时同步数据库方式来进行，避免同时操数据库）

TODO

问题虽然解决了。但是原理还不清楚，需要继续深挖。

为什么 createBean 对性能影响这么大？

如果影响这么大，Spring 为什么还要有多例？首先非并发场景速度还是很快的。这个毋庸置疑。毕竟接口响应时间不足 50 ms。所以问题一定出在，并发 createBean 同一对象的锁等待场景。根据堆栈日志，翻了一下 Spring 源码，果然发现这里出现了同步锁。相信锁肯定不止一处。

org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#doCreateBean

System.currentTimeMillis 并发度多少才会对性能产生影响，影响有多大？

很多公司（包括大厂）在业务代码中，还是会频繁的使用 System.currentTimeMillis 获取时间戳。比如：时间字段赋值场景。所以，性能影响肯定会有，但是影响的门槛是不是很高。

继续学习性能优化知识

吞吐量与什么有关？

首先，接口响应时长。直接影响因素还是接口响应时长，响应时间越短，吞吐量越高。一个接口响应时间 100ms,那么 1s 就能处理 10 次。

其次，线程数。现在都是多线程环境，如果同时 10 个线程处理请求，那么吞吐量又能增加 10 倍。当然由于 CPU 资源有限，所以线程数也会受限。理论上，在 CPU 资源利用率较低的场景，调大 tomcat 线程数，以及并发数，能够有效的提升吞吐量。

最后，高性能代码。无论接口响应时长，还是 CPU 资源利用率，都依赖于我们的代码，要做高性能的方案设计，以及高性能的代码实现，任重而道远。

CPU使用率的高低与哪些因素有关？

CPU 使用率的高低，本质还是由线程数，以及 CPU 使用时间决定的。

假如一台 10 核的机器，运行一个单线程的应用程序。正常这个单线程的应用程序会交给一个 CPU 核心去运行，此时占用率就是 10%。而现在应用程序都是多线程的，因此一个应用程序可能需要全部的 CPU 核心来执行，此时就会达到 100%。

此外，以单线程应用程序为例，大部分情况下，我们还涉及到访问 Redis/Mysql、RPC 请求等一些阻塞等待操作，那么 CPU 就不是时刻在工作的。所以阻塞等待的时间越长，CPU 利用率也会越低。也正是因为如此，为了充分的利用 CPU 资源，多线程也就应运而生（一个线程虽然阻塞了，但是 CPU 别闲着，赶紧去运行其他的线程）。

一个服务线程数在多少比较合适（算上 Tomcat，最终的线程数量是 226），执行过程中发现即使tomcat线程数量是 100，活跃线程数也很少超过 50，整个压测过程基本维持在 20 左右。