记一次压测QPS上不去的排查经历

背景

由于架构变更，服务与服务之间职责发生变更，故而进行项目重构，而个人中心，是一个重要的入口，该接口开发后，需要进行压测，并结合线上的访问量，进而评估所需要的资源

问题

压测过程中，随着并发数的增加，CPU占用越来越高，但是TPS却依旧没有什么变化，对比之前老系统的压测结果，明显就有异常

因为下游系统并不是直接调用真实系统，而是mock，之前也有这种情况，mock占用资源导致TPS上不去的情况，所以让测试将下游系统也部署上去，真实调用下游看看压测结果，发现还是一样，没有改变

排查

1.通过日志排查

因为能直接接触到的，就是日志了，通过日志分析接口，发现大部分接口耗时都好几秒，然后看调用下游，调用redis前后的日志，发现调用的耗时其实算是正常的；去看其他日志的打印间隔，发现有两行日志之间的时间间隔比较大，定位到代码具体位置，发现这两行日志之间其实都没啥逻辑，对比该接口其他日志结果，发现耗时的地方并不相同，猜想是full gc导致的停顿

2.通过gc日志验证猜想

找到gc日志，查询到所有full gc的日志，发现确实full gc挺频繁的，但是光看gc日志，并不能得出什么信息

3.通过工具定位原因

使用jdk自带的监测工具jvisualvm.exe（jdk/bin目录中）

连接到远程应用，需要应用启动的时候增加JVM参数，暴露出端口，才可以通过下图红框来连接，这里通过本地连接做个样例

连接后，整个界面大概就是这样，首页的看板，可以实时反应出CPU，堆情况等信息

当时CPU的情况大概如下图红线（所有图标，都大概画了当时的情形，以红线为准）

压测的整个过程，CPU直接满载了，并且居高不下，一直到压测结束，才降下来

看堆的情况，发现gc频繁，但是gc的曲线如下图红线，每次触发gc后，都只回收一部分，另一部分回收不掉，堆内存持续增长。这样应用运行久了，肯定会内存溢出的。

初步猜测，应该是一直产生大对象，并且被长时间持有，释放不了

通过抽样器，大概反应出堆的情况，发现并没有持有大对象，没有异常的情况，就很奇怪，为什么一直堆一直回收不了，一直持续增长？

下图只是说明在哪里看，给个示例

观察一下CPU的情况，发现有几个方法，一直占用了大量的CPU资源，而且都是日志打印的方法，这就很不对劲了

代码定位到具体的类，发现是做日志脱敏的日志扩展类

下图只是说明在哪里看，给个示例

所以到这里可以初步认定是日志脱敏消耗了大量的CPU资源导致的

4.验证结论

尝试着关掉日志脱敏，重新进行压测，发现压测结果正常，随着并发数的增加，TPS也增加了，CPU正常上升，不存在大量接口延时的情况

观察堆的情况，发现垃圾回收没有那么频繁了，并且触发垃圾回收后，也能回收掉所有垃圾，如下图红线，很平稳，不像之前堆内存一直在持续增长，所以这里验证了前一步的猜想，是日志脱敏导致的

5.解决方案

由于监管要求，日志脱敏并不能关闭，所以得另外找解决办法，既然是日志脱敏消耗大量的CPU资源，那只能对日志进行处理了

分析发现，因为内部框架对于请求/响应报文重复打印了好几次，并且有两个接口，是存在大报文的（由于工作量原因，某些配置表当期没安排迁移，只能通过老系统提供接口，获取整个配置表）

尝试着把这两个接口的配置都清空，开启日志脱敏的情况下，再进行压测，发现堆内存变化也是正常的

因为配置表暂时没人力可以做迁移，最后只能推动框架的负责人，优化日志，减少日志重复打印，避免日志脱敏占用大量CPU资源，但是隐患依旧是存在的，后续推动配置表的迁移

原因

日志脱敏，因为需要做正则匹配，但是大量的日志，以及都是大报文，会消耗特别多的CPU资源

系统是对C的，为了减少延迟，使用的是CMS垃圾回收器

CMS垃圾回收器，触发一次full gc，只会在初期暂停所有应用线程，标记没有被引用的对象，后面并发标记和并发回收，并不会暂停应用，这样是为了减少应用的延迟时间，但由于CPU资源被日志脱敏大量消耗了，导致垃圾回收线程抢占不到CPU资源，回收缓慢，旧垃圾没回收完，新垃圾又产生，堆内存就呈现出持续增长的情况