记录一次线上系统CPU飙高的问题与排查

站长

2024年04月03日 12:29 · 阅读数 4

1 现象

审核服务，部署之后，CPU会逐渐上升，如果长时间【比如一些长假期】不重新部署，最后会触发cpu 超过80% 的报警。如下图所示：

记录一次线上系统CPU飙高的问题与排查

2 排查过程

2.1 春节第一次报警

之前春节假期的时候，报警了。当时只是对一些常用的线程池使用不当的地方进行了优化【比如每次请求来了，会新建一个线程池，并没有很好地利用线程池的特性】。并且对线程进行了dump，增加了GC日志输出。当时并没有jvm 线程相关的监控，并且自己也没有找到很好用的工具进行线程分析，所以就搁置了。

2.2 加入jvm监控，又一次报警

2.3 五一假期再次报警

再后来，就到了五一假期，服务又一次报警了，还是CPU报警。通过自己写的工具，发现还是io.micrometer 相关的线程耗时高。自己很奇怪，之前已经把自己引入的 Actuator 排除了，怎么还有？于是再次排查代码，发现在dao模块中，之前其他同学引入了 Actuator 。这儿为什么会引入actutor ？于是排除 actutor 启动服务，结果报错了。是mybatis-plus 需要依赖actutor。

既然知道是这个地方导致cpu高，那我就去看下到底是因为什么导致的CPU高？之前自己的脚本只能简单的知道哪儿高，但是具体耗时多少，还是看不出来。自从第二次排查之后，自己也进一步了解了CPU排查的工具，比如async-profiler, arthas。这次利用arthas 工具，导出了火焰图。

记录一次线上系统CPU飙高的问题与排查

产生了大平层。。。

于是又进一步使用arthas 查看具体到方法的耗时:

trace io.micrometer.core.instrument.MeterRegistry accept -n 5

结果是这样的：

Press Q or Ctrl+C to abort.
Affect(class-cnt:3 , method-cnt:1) cost in 329 ms.
`---ts=2020-05-08 00:59:28;thread_name=http-nio-8080-exec-96;id=1573;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@52341af1
    `---[81.505142ms] io.micrometer.core.instrument.MeterRegistry:accept()
        +---[min=0.004764ms,max=81.319737ms,total=81.324501ms,count=2] io.micrometer.core.instrument.config.MeterFilter:accept() #582
        `---[min=9.37E-4ms,max=0.00386ms,total=0.004797ms,count=2] io.micrometer.core.instrument.config.MeterFilterReply:ordinal() #582

`---ts=2020-05-08 00:59:28;thread_name=http-nio-8080-exec-89;id=156c;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@52341af1
    `---[154.791256ms] io.micrometer.core.instrument.MeterRegistry:accept()
        +---[min=0.007216ms,max=154.698631ms,total=154.705847ms,count=2] io.micrometer.core.instrument.config.MeterFilter:accept() #582
        `---[min=8.55E-4ms,max=8.63E-4ms,total=0.001718ms,count=2] io.micrometer.core.instrument.config.MeterFilterReply:ordinal() #582

`---ts=2020-05-08 00:59:28;thread_name=http-nio-8080-exec-77;id=155f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@52341af1
    `---[180.919824ms] io.micrometer.core.instrument.MeterRegistry:accept()
        +---[min=0.005424ms,max=180.827584ms,total=180.833008ms,count=2] io.micrometer.core.instrument.config.MeterFilter:accept() #582
        `---[min=5.44E-4ms,max=0.001344ms,total=0.001888ms,count=2] io.micrometer.core.instrument.config.MeterFilterReply:ordinal() #582

`---ts=2020-05-08 00:59:28;thread_name=http-nio-8080-exec-25;id=59;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@52341af1
    `---[148.492822ms] io.micrometer.core.instrument.MeterRegistry:accept()
        +---[min=0.004606ms,max=148.420117ms,total=148.424723ms,count=2] io.micrometer.core.instrument.config.MeterFilter:accept() #582
        `---[min=5.37E-4ms,max=7.58E-4ms,total=0.001295ms,count=2] io.micrometer.core.instrument.config.MeterFilterReply:ordinal() #582

`---ts=2020-05-08 00:59:28;thread_name=http-nio-8080-exec-109;id=1581;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@52341af1
    `---[161.933738ms] io.micrometer.core.instrument.MeterRegistry:accept()
        +---[min=0.004528ms,max=161.862203ms,total=161.866731ms,count=2] io.micrometer.core.instrument.config.MeterFilter:accept() #582
        `---[min=7.23E-4ms,max=7.86E-4ms,total=0.001509ms,count=2] io.micrometer.core.instrument.config.MeterFilterReply:ordinal() #582

我擦，一个filter 耗时180ms。。。

3 问题分析

既然找到了耗时点，那么如下几个问题就得找一下答案：

mybatis-plus 依赖 Actuator 干什么？

用了actutor CPU 为什么高？

3.1 mybatis-plus 依赖 Actuator 干什么？

查了一些资料，发现 mybatis-plus 在多数据源模块进行主从切换时会依赖检查，而检查时需要 Actuator 统计一些耗时之类的。其实mybatis-plus 在启动时已经默认关闭检查，但是在主从切换时还是要检查，所以即使默认关闭，也没用。并且没有开放给用户参数，去修改这个逻辑。按照下面这篇文章的意思，其实这是个bug, 一个无用的功能导致引入了不必要依赖。 gitee.com/baomidou/dy…

3.2 Actuator 与 micrometer

记录一次线上系统CPU飙高的问题与排查

3.2.1 spring boot 的filter

从上面章节的火焰图中我们可以看出，每次请求到来，spring boot 的过滤器（如果对过滤器不是很熟悉，可以参考yq.aliyun.com/articles/68… ）会执行OncePerRequestFilter.doFilter 。然后doFilter 采用了责任链模式，会依次多个过滤器，而micrometer 中的 MeterFilter 就是一种过滤器，在我们这个case中，就是因为这个过滤器 MeterFilter 导致的CPU高。下面我们看下这个filter 是怎么通过actuator 加载到spring boot 中来的, 也就是看下 Actuator 与 micrometer 之间的一个关系。

3.2.2 micrometer 的结构

讲 Actuator 与 micrometer 关系之前，得简单补充一点micrometer 的知识。之前对 micrometer 并不是很清楚，这次简单调研了一下。（1）meter （计量器）作为一个监控组件，肯定要各种统计，在micrometer 中，这叫做meter（计量器）。micrometer会有各种不同的计量器，有一些默认的计量器（比如火焰图中的Timer），也允许用户自己定义。（2）meterRegistry （计量器注册表）那么meter 是怎么来的呢？就是通过meterRegistry （计量器注册表）来产生的，比如火焰图中的MeterRegitstry。同样 Registry 也有好多种，并且有组合模式。后面将会简单讲到，Actutor 就是注册了一个组合的Registry。（3）meterFilter （计量器过滤器）每个计量器，得决定哪些需要统计，哪些不需要，这就是计量器对应的过滤器要干的事情了。

总结一下，micrometer 的结构可以简单理解成下面这张图：

记录一次线上系统CPU飙高的问题与排查

这部分参考了使用 Micrometer 记录 Java 应用性能指标

3.2.3 Actuator 与 micrometer 的关系

Spring Boot 自动配置一个组合的MeterRegistry，并添加一个registry到这个组合MeterRegistry中。

这部分参考自 Micrometer 快速入门

3.3 MeterFilter 为什么会导致CPU高？

再看下火焰图：

记录一次线上系统CPU飙高的问题与排查

结合火焰图，我们可以看到耗时都在MeterFilter.accept 这个方法。那我们看下这个方法到底干了什么？

private boolean accept(Meter.Id id) {
        for (MeterFilter filter : filters) {
            switch (filter.accept(id)) {
                case DENY:
                    return false;
                case ACCEPT:
                    return true;
            }
        }

        return true;
    }

就遍历filters 列表，然后执行了filter 的accept方法:

 default MeterFilterReply accept(Id id) {
        return MeterFilterReply.NEUTRAL;
    }

filter.accept(id) 只是一个简单的比较。单次执行不会很耗时。 filters 是一个 CopyOnWriteArrayList， CopyOnWriteArrayList 使用了可重入锁，是线程安全的，写时加锁，但是支持读并发。

结合火焰图，应该是list太大，导致即使读 + 比较，也特别耗时。服务刚刚发布时，测试这儿耗时才不到1ms ，随着发布部署时间的推移，这儿要180ms。这也跟我们的问题现象吻合。 由于这是一个内部依赖的组件，我们不能再进一步看filters 到底有多大，很遗憾。使用了arthas redefine 功能，也没成 alibaba.github.io/arthas/rede… ，这儿先暂时几个TODO，后续有时间再研究。不过庆幸的是，从网上也找到了一个相似的案例，是因为filters 过大导致的类似问题。 www.cnblogs.com/bingjava/p/… 。

3.4 原因总结

引入了spring actuator, 注册了 MetricsClientHttpRequestInterceptor，导致每次请求都会被MetricsClientHttpRequestInterceptor 拦截，随着统计请求的增多， ConcurrentSkipListMap越来越大，遍历处理特别耗cpu.

4 解决方案

重写了http 请求的RestTemplate，对 MetricsClientHttpRequestInterceptor 拦截器进行了删除（也可以针对特定请求uri 对拦截器进行定制化开发，后续如果使用这个拦截器，再特殊处理。）


```
@Bean
public RestTemplate restTemplate(RestTemplateBuilder restTemplateBuilder) {
    RestTemplate restTemplate = restTemplateBuilder.build();
    removeMetricsClientHttpRequestInterceptor(restTemplate);
    return restTemplate;
}
```


/**
 * 过滤掉MetricsClientHttpRequestInterceptor。 因为随着对外请求次数增加，计算metrics 拦截器的统计Set 的size 时，会导致CPU彪高。
 * 如果后续还想使用这个拦截器，可以针对拦截器的高频URL 进行过滤。而不是对整个拦截器过滤。
 * @param restTemplate
 */
private void removeMetricsClientHttpRequestInterceptor(RestTemplate restTemplate) {
    List<ClientHttpRequestInterceptor> existingInterceptors = restTemplate
            .getInterceptors();
    // 重新组装 interceptors， 并重新插入restTemplate
    List<ClientHttpRequestInterceptor> newInterceptors = new ArrayList<>();
    for (ClientHttpRequestInterceptor interceptor : existingInterceptors) {
        String interceptorName = interceptor.getClass().getSimpleName();
        // 过滤  MetricsClientHttpRequestInterceptor ， 其他拦截器插入。
        if (!"MetricsClientHttpRequestInterceptor".equals(interceptorName)) {
            newInterceptors.add(interceptor);
        }
    }
    restTemplate.setInterceptors(newInterceptors);
}

5 试验结果

(a)实验机器cpu稳定，对照机器飙升：相同的流量，实验机器一直稳定在%5 的cpu 使用率。而对照机器cpu 逐渐上升，对比了2个小时，已经到了59%，是实验机器的十倍左右。如果继续实验，对照机器会一直直线上升。

对照机器：

记录一次线上系统CPU飙高的问题与排查

实验机器

记录一次线上系统CPU飙高的问题与排查

(b)审核机器缩减：配置相同的机器，审核ct 机器数已经从10台缩减到3台，并且这2台一直维持在10% 以内的cpu使用率。