⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 juejin.cn/post/7185479136599769125 「FishBones」欢迎转载，保留摘要，谢谢！

🙂🙂🙂关注**微信公众号：【芋道源码】**有福利：

RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表

RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址

您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。

新的源码解析文章实时收到通知。每周更新一篇左右。

认真的源码交流微信群。

背景

公司的一个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：

这里感谢一下huoger 同学的评论，当时还误以为该方式能够降低性能的影响，但是实际上也只是一层封装。底层使用的是 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为什么还要有多例？

首先非并发场景速度还是很快的。这个毋庸置疑。毕竟接口响应时间不足50ms。

所以问题一定出在，并发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左右。

芋道源码 —— 纯源码解析博客

高端操作，只改了五行代码接口吞吐量提升了10多倍

背景