关于node.js:只改了五行代码接口吞吐量提升了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：
这里感激一下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 : 内存大小，调配，垃圾收集器都想换...

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