关于node.js:只改了五行代码接口吞吐量提升了10多倍

3次阅读

共计 7443 个字符，预计需要花费 19 分钟才能阅读完成。

背景
公司的一个 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 : 内存大小，调配，垃圾收集器都想换 …

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

正文完