背景

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

背景

分析进程

定位“慢”原因

持续定位“慢”的原因

定位CPU运用率高的原因

总结

TODO

作者信息

只改了五行代码接口吞吐量提升了10多倍

背景

分析进程

定位“慢”原因

持续定位“慢”的原因

定位CPU运用率高的原因

总结

TODO

相关文章

2022，拔剑四顾心茫然

RabbitMq消息丢失原因及其解决方案

【Java并发编程 第四章】无锁并发

简单聊聊内存逃逸 ｜ 剑指offer – golang

作者信息

【Java并发编程第四章】无锁并发

简单聊聊内存逃逸｜剑指offer – golang