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

Posted 2023-02-22 程序员的店小二

背景

某公司的一个 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 左右。