来源https://juejin.cn/post/7185479136599769125目录背景分析过程定位慢原因继续定位慢的原因定位 CPU 使用率高的原因总结吞吐量与什么有关CPU 使用率的高低与哪些因素有关TODO背景公司的一个 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 wheretype 1 and filed 1;上述 SQL 相当于并发操作同一条数据肯定存在锁等待。日志显示此处的等待耗时占接口总耗时 80% 以上。二话不说先改为敬。因为是压测环境直接改为异步执行确认一下效果。“PS当时心里是这么想的妥了大功告成。就是这里的问题绝壁是这个原因优化一下就解决了。当然如果这么简单就没有必要写这篇文章了...优化后的效果优化后效果嗯...emm...好这个优化还是很明显的提升提升了近 2 倍。此时已经感觉到有些不对了慢 SQL 已经解决了异步了~ 随便吧~ 你执行 10s 我也不管了虽然对吞吐量的提升没有预期的效果。但是数据是不会骗人的。最大值已经从5s - 2s百分位值4s - 1s这已经是很大的提升了。加入小哈的星球你将获得:专属的项目实战4个项目 / 1v1 提问 / 简历修改 /Java 学习路线 /社群讨论 /学习打卡 / 每月赠书《仿小红书微服务架构》 已完结基于 Spring Cloud Alibaba Spring Boot 3.x JDK 17..., 点击查看项目介绍演示地址http://116.62.199.48:7070/《Spring AI 应用RAG 智能客服》已完结, 基于 Spring AI Spring Boot 3.x JDK 21《秒杀系统设计》正在更新中单体到微服务高并发架构演进《前后端分离博客项目全栈开发》已完结,演示链接http://116.62.199.48/项目阅读地址https://quanxiaoha.com/column截止目前累计输出 120w 字讲解图 4013 张还在持续爆肝中..戳我加入学习解锁全部项目已有4500小伙伴加入继续定位慢的原因通过第一阶段的优化我们距离目标近了很多。废话不多说继续下一步的排查。我们继续看日志此时日志出现类似下边这种情况2023-01-0415:17:05:347 INFO **.**.**.***.50 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415:17:05:348 INFO **.**.**.***.21 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415:17:05:350 INFO **.**.**.***.47 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415:17:05:465 INFO **.**.**.***.234 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415:17:05:467 INFO **.**.**.***.123 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415:17:05:581 INFO **.**.**.***.451 [TID: 1s22s72s8ws9w00] ********************** 2023-01-0415: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% 以内。类似于下图不过有很多线程。CPU线程占用没有很高就证明大家都很正常只是多而已...此时没有下一步的排查思路了。当时想着算了打印一下堆栈看看吧看看到底干了啥~在看的过程中发现这段日志http-nio-6071-exec-9#82 daemon prio5 os_prio0 tid0x00007fea9aed1000 nid0x62 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) publicclassRedisMasterimplementsIRedisTool{ // ...... }没错就是用了多例。而且使用的地方是 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 源码果然发现这里出现了同步锁。相信锁肯定不止一处。Spring源码同步锁org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#doCreateBeandoCreateBeanSystem.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 左右。加入小哈的星球你将获得:专属的项目实战4个项目 / 1v1 提问 / 简历修改 /Java 学习路线 /社群讨论 /学习打卡 / 每月赠书《仿小红书微服务架构》 已完结基于 Spring Cloud Alibaba Spring Boot 3.x JDK 17..., 点击查看项目介绍演示地址http://116.62.199.48:7070/《Spring AI 应用RAG 智能客服》已完结, 基于 Spring AI Spring Boot 3.x JDK 21《秒杀系统设计》正在更新中单体到微服务高并发架构演进《前后端分离博客项目全栈开发》已完结,演示链接http://116.62.199.48/项目阅读地址https://quanxiaoha.com/column截止目前累计输出 120w 字讲解图 4013 张还在持续爆肝中..戳我加入学习解锁全部项目已有4500小伙伴加入1. 我的私密学习小圈子从0到1手撸企业实战项目~ 2. SpringBoot 快速实现 api 加密一个轮子搞定 3. 面试官线程池有几种创建方式 4. 面试官Feign 第一次调用为什么会很慢大部分人答不上来最近面试BAT整理一份面试资料《Java面试BATJ通关手册》覆盖了Java核心技术、JVM、Java并发、SSM、微服务、数据库、数据结构等等。 获取方式点“在看”关注公众号并回复 Java 领取更多内容陆续奉上。PS因公众号平台更改了推送规则如果不想错过内容记得读完点一下“在看”加个“星标”这样每次新文章推送才会第一时间出现在你的订阅列表里。 点“在看”支持小哈呀谢谢啦