AI 助理
备案控制台
开发者社区 开发与运维 文章 正文

线上频繁fullgc问题-SpringActuator的坑

2024-06-04 267
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
本文涉及的产品
Redis 开源版，标准版 2GB
推荐场景：
搭建游戏排行榜
云数据库 Tair（兼容Redis），内存型 2GB
推荐场景：
通过缓存加速数据库访问
简介： 偷偷开启的监控在吃内存

原文首发于博客园：https://www.cnblogs.com/qisi/p/-/gc_spring_meter

整体复盘：

一个不算普通的周五中午，同事收到了大量了cpu异常的报警。根据报警表现和通过arthas查看，很明显的问题就是内存不足，疯狂无效gc。而且结合arthas和gc日志查看，老年代打满了，gc不了一点。既然问题是内存问题，那么老样子，通过jmap和heap dump 文件分析。
不感兴趣的可以直接看结论

  1. 通过jmap命令查看的类似下图，并没有项目中明显的自定义类，而占空间最大的又是char数组，当时线上占900M左右，整个老年代也就1.8个G；此时dump文件同事还在下载，网速较慢。
    image.png

  2. 通过业务日志查看，很多restTempalte请求报错，根据报错信息可知是某xx认证过期了，导致接收到回调，业务处理时调接口报错了；查询数据库，大概有20多万回调。根据过期时间和内存监控，大概能对的上号，表明内存异常和这个认证过期有关。怀疑度最高的只有回调以及回调补偿任务，但是一行一行代码看过去，并不觉得有什么异常。

    下载完dump文件后，先重启了服务器，避免影响业务，然后着手分析文件。

  3. 在dump文件下载完之后，使用jvisualvm分析，最多的char里大部分都是一些请求的路径，如“example/test/1"，”“example/test/2"之类的，都是接口统一，但是参数不一样，因为是GET请求，所以实际路径都不一样。Jvisualvm点击gc_root又一直计算不出来，在等待计算的过程中，一度走了弯路
    image.png

    于是又现下载jprofiler，通过jprofiler的聚类，确定了一定是这个Meter导致的，而通过JProfile的分析，终于定位到是
    org.springframework.boot.actuate.metrics.web.client.MetricsClientHttpRequestInterceptor#intercept这个类。然后发现，MetricsClientHttpRequestInterceptor 持有一个meterRegistry，里面核心是个map，所以是map没有清除。根据依赖分析，发现是有次需求引入了redisson-spring-boot-starter，而redisson依赖了spring-boot-starter-actuator，这东西默认启动了，会拦截所有的RestTempalte请求，然后记录一些指标。
    image.png
    image.png

所以问题变成了，为什么map没有清掉已经执行完的请求？
我之前并没有研究过spring的actuator，只是看过skywalking的流程，所以我以为也和skywalking一样，记录然后上报，上报之后删除本地的。所以当时怀疑，难道是和我们请求都异常了有关，但是正如下面的代码，无论是否异常，都是执行finnally，所以又不太可能。

ClientHttpResponse response = null;
try {
   response = execution.execute(request, body);
   return response;
}
finally {
   try {
      getTimeBuilder(request, response).register(this.meterRegistry).record(System.nanoTime() - startTime,
            TimeUnit.NANOSECONDS);
   }
   catch (Exception ex) {
      logger.info("Failed to record metrics.", ex);
   }
   if (urlTemplate.get().isEmpty()) {
      urlTemplate.remove();
   }
}

而在我自己尝试复现之后，meterRegistry的指标根本不会被自动清除，生命周期和应用的生命周期一样。因为并不存在上报，数据全部在内存（虽然可以导出到数据库，但并没有深入研究）。其实也合理，因为如果要通过Grafana等可视化平台查看的时候，我们也希望查看任意时刻的监控。而且其有一个属性是maxUriTags，默认值是100，其作用是限制meterMap里uri的个数，理论上并不会记录太多。

结论

所以到此为止，可以定结论，那就是因为引入了redisson-spring-boot-starter，导致不知情引入了spring-boot-starter-actuator。
因此默认开启了http.client.request指标的监控，关于http.client.request，有一个属性是maxUriTags，默认值是100，其作用是限制meterMap里uri的个数。但是maxUriTags起作用的地方MeterFilter没有生效。
由于maxUriTags没有生效，导致监控信息里的uri因为业务大量的GET请求中存在唯一id，本身就很占内存。压死内存的最后稻草是认证过期和补偿任务。补偿任务为保证及时性一直在频繁执行，而接口的uri里两个变量（token和uniId）导致meterMap里的key不重复，一直在插入，20万回调，token两小时更新一次，持续了两天，最终产生了124万条字符串，被map持有，无法回收。

解决方案

  1. 不需要监控
    直接排除掉spring-boot-starter-actuator
  2. 需要监控但不需要http.client.request指标
     management:
   metrics:
     web:
       client:
         request:
           autotime:
             enabled: false
  3. 需要http.client.request指标
    jar包升到2.5.1或以上
     <dependency>
     <groupId>org.springframework.boot</groupId>
     <artifactId>spring-boot-actuator-autoconfigure</artifactId>
     <version>2.5.1</version>
 </dependency>

复现：

新建测试项目
image.png

相关代码和配置如下

@SpringBootApplication
@Slf4j
public class Application {
    public static void main(String[] args) {
        ConfigurableApplicationContext run = SpringApplication.run(Application.class);
        RestTemplate bean = run.getBean(RestTemplate.class);
        for (int i = 0; i < 300000; i++) {
            try {
                String forObject = bean.getForObject("http://localhost:9999/first/echo?i="+i, String.class);
            }catch (Exception e){
                log.error("执行"+i+"次");
            }
        }
    }
}

@Configuration
public class RestTemplateTestConfig {
    @Bean
    public RestTemplate restTemplate(RestTemplateBuilder builder){
        return builder.build();
    }
}

<dependencies>
    <dependency>
        <groupId>org.redisson</groupId>
        <artifactId>redisson-spring-boot-starter</artifactId>
        <version>3.13.1</version>
    </dependency>
    <dependency>
        <groupId>org.apache.httpcomponents</groupId>
        <artifactId>httpclient</artifactId>
    </dependency>
</dependencies>

server:
  port: 8080
spring:
  redis:
    host: ************
    password: **********
#management:
#  endpoints:
#    web:
#      exposure:
#        include: "metrics"
#  metrics:
#    web:
#      client:
#        request:
#          autotime:
#            enabled: false

启动项目通过jconsole查看整个堆的监控和老年代监控分别如下，可以看出老年代一直在增长，并不会回收
image.png
image.png

甚至手动触发GC，老年代也回收不了

[Full GC (System.gc()) [Tenured: 195217K->195457K(204800K), 0.3975261 secs] 233021K->195457K(296960K), [Metaspace: 30823K->30823K(33152K)], 0.3976223 secs] [Times: user=0.39 sys=0.00, real=0.40 secs]

通过jprofiler确定主要是meterMap占据内存了，最多的都是字符串。
image.png
image.png

分析

actuator导致rest启动了metrics记录
在使用RestTemplateBuilder构建RestTemplate的时候，会触发懒加载的RestTemplateAutoConfiguration里的RestTemplateBuilderConfigurer，在此期间，config中会注入RestTempalteCustomizer类型的bean。
image.png

而项目中引用了redisson-spring-boot-starter，从依赖分析可以看出间接引用了actuator相关的包。
image.png

这导致会在RestTemplateMetricsConfiguration配置类中实例化一个叫做MetricsRestTemplateCustomizer的bean，这个bean会通过上面的restTepalteBuilderConfigurer.configure方法给restTemplate添加拦截器MetricsClientHttpRequestInterceptor。
image.png

拦截器的intercept方法会在finnally中最终记录此次请求的一些指标
image.png

io.micrometer.core.instrument.Timer.Builder#register->
io.micrometer.core.instrument.MeterRegistry#time->
io.micrometer.core.instrument.MeterRegistry#registerMeterIfNecessary->
io.micrometer.core.instrument.MeterRegistry#getOrCreateMeter{
meterMap.put(mappedId, m);
}

image.png

最终存到了是SimpleMeterRegistry这个bean的meterMap中去，这个bean也是actuator-autoconfigure自动注入的
image.png

但是到目前为止，只是启动了metrics记录，假如maxUriTags有效的话，会在超过100条记录后getOrCreateMeter方法里的accept这里过滤掉，并不会走到下面的meterMap.put(mappedId, m)
image.png

为什么maxUriTags没有生效？

maxUriTags只在下图这个位置使用了，作用是构建了一个MeterFilter，根据debug我们可以确定bean是产生了的
image.png

但是在accept这里打上断点，再触发一些请求可以发现，代码并不会走到这里
image.png

往上跟，没有走到这里的情况只能是filters里没有这个MeterFilter，但我们刚才又确定metricsHttpCLientUriTagFilter这个bean是产生了的，那么就只能是没有添加到filters，也就是没有调用过meterFilter
image.png
image.png

从meterFilter往上只有可能是addFilters，一层一层往上最终到了MeterRegistryPostProcessor#postProcessAfterInitialization这个方法
image.png
image.png
image.png

我们上面说过负责记录的bean叫做simpleMeterRegistry，但是我们在这里打上条件断点发现并没有走到这里
image.png

找到SimpleMeterRegistry和MeterRegistryPostProcessor这两个bean注入的地方打断点观察，都产生了，且MeterRegistryPostProcessor比SimpleMeterRegistry产生的要早
image.png
image.png

理论上没问题，但现在确实没走到，所以只能在SimpleMeterRegistry产生的时候在org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#applyBeanPostProcessorsAfterInitialization打断点，然后可以发现，在simpleMeterRegistry实例化快结束的时候，调用后处理器时this.beanPostProcessors确实没有MeterRegistryPostProcessor
image.png
image.png

一般来说，postPorcessor的bean注入是在refresh方法的registerBeanPostProcessors中，是早于普通bean的实例化
image.png

所以simpleMeterRegistry实例化的时候没有MeterRegistryPostProcessor是不合理的情况，定位simpleMeterRegistry是何时实例化的成了关键问题

simpleMeterRegistry的实例化时机

在new SimpleMeterRegistry这里打上断点观察堆栈发现，simpleMeterRegistry是MetricsRepositoryMethodInvocationListener的参数，MetricsRepositoryMethodInvocationListener则是metricsRepositoryMethodInvocationListenerBeanPostProcessor的参数
所以是在实例化metricsRepositoryMethodInvocationListenerBeanPostProcessor这个处理器的时候，因为依赖导致先实例化了simpleMeterRegistry这个bean依赖
image.png
image.png
image.png
image.png

导致实例化了SimpleMeterRegistry，而这个时候由于没有注册，所以SimpleMeterRegistry在执行applyBeanPostProcessorsAfterInitialization时就执行不到meterRegistryPostProcessor了
image.png
image.png

spring已经修复了这个问题，spring-boot-actuator-autoconfigure版本大于2.5.0的都已经没有问题了。解决方案
2.5.1 版本中，添加了一个这个ObjectProvider，在源头上不会立即把依赖的bean初始化完
image.png
image.png

2.5.0 版本
image.png

public Object resolveDependency(DependencyDescriptor descriptor, @Nullable String requestingBeanName,
      @Nullable Set<String> autowiredBeanNames, @Nullable TypeConverter typeConverter) throws BeansException {

   descriptor.initParameterNameDiscovery(getParameterNameDiscoverer());
   if (Optional.class == descriptor.getDependencyType()) {
      return createOptionalDependency(descriptor, requestingBeanName);
   }
   //由于使用了ObjectProvider，所以这里只是返回了一个DependencyObjectProvider
   else if (ObjectFactory.class == descriptor.getDependencyType() ||
         ObjectProvider.class == descriptor.getDependencyType()) {
      return new DependencyObjectProvider(descriptor, requestingBeanName);
   }
   else if (javaxInjectProviderClass == descriptor.getDependencyType()) {
      return new Jsr330Factory().createDependencyProvider(descriptor, requestingBeanName);
   }
   else {
   //2.5.0版本中会在这个方法加载入参依赖的bean
      Object result = getAutowireCandidateResolver().getLazyResolutionProxyIfNecessary(
            descriptor, requestingBeanName);
      if (result == null) {
         result = doResolveDependency(descriptor, requestingBeanName, autowiredBeanNames, typeConverter);
      }
      return result;
   }
}
文章标签：
云数据库 Tair（兼容 Redis）
监控
Java
测试技术
Arthas
数据库
起司
目录
相关文章
nodejh
|
Prometheus 监控 Kubernetes
使用 Prometheus + Grafana 监控 k8s 上的 Spring Boot 应用
本文主要介绍如何使用 Prometheus 和 Grafana 可视化监控运行在 k8s 上的 Spring Boot 应用，监控指标包括 CPU、内存、线程信息、日志信息、HTTP 请求、JVM 等。
nodejh
4025 0
使用 Prometheus + Grafana 监控 k8s 上的 Spring Boot 应用
小Lee
|
10月前
|
存储 分布式计算 监控
大数据数据倾斜处理
【11月更文挑战第4天】
小Lee
519 7
蓝易云
|
4月前
|
缓存 Java 数据库
SpringBoot集成Ehcache缓存使用指南
以上是SpringBoot集成Ehcache缓存的基本操作指南，帮助你在实际项目中轻松实现缓存功能。当然，Ehcache还有诸多高级特性，通过学习和实践，你可以更好地发挥它的威力。
蓝易云
457 20
灵杰开发者
|
11月前
|
SQL Java API
Apache Flink 2.0-preview released
Apache Flink 社区正积极筹备 Flink 2.0 的发布，这是自 Flink 1.0 发布以来的首个重大更新。Flink 2.0 将引入多项激动人心的功能和改进，包括存算分离状态管理、物化表、批作业自适应执行等，同时也包含了一些不兼容的变更。目前提供的预览版旨在让用户提前尝试新功能并收集反馈，但不建议在生产环境中使用。
灵杰开发者
1489 13
Apache Flink 2.0-preview released
小忽悠
|
安全 Java API
Spring Security实现RBAC权限管理
Spring Security实现RBAC权限管理 一简介 在企业应用中，认证和授权是非常重要的一部分内容，业界最出名的两个框架就是大名鼎鼎的 Shiro和Spring Security。
小忽悠
6966 0
技术自由圈/原疯狂创客圈
|
11月前
|
NoSQL Java Redis
太惨痛： Redis 分布式锁 5个大坑，又大又深， 如何才能 避开 ？
Redis分布式锁在高并发场景下是重要的技术手段，但其实现过程中常遇到五大深坑：**原子性问题**、**连接耗尽问题**、**锁过期问题**、**锁失效问题**以及**锁分段问题**。这些问题不仅影响系统的稳定性和性能，还可能导致数据不一致。尼恩在实际项目中总结了这些坑，并提供了详细的解决方案，包括使用Lua脚本保证原子性、设置合理的锁过期时间和使用看门狗机制、以及通过锁分段提升性能。这些经验和技巧对面试和实际开发都有很大帮助，值得深入学习和实践。
技术自由圈/原疯狂创客圈
1960 1
太惨痛： Redis 分布式锁 5个大坑，又大又深， 如何才能 避开 ？
游客otvqgjsxhwuvm
|
存储 缓存 运维
有关一次FullGC的故障排查
在收到容器CPU使用率达到104%的告警后，通过日志发现多个线程正在进行批处理任务。初步怀疑Full GC导致CPU占用过高，但内存使用率仅为62%，不符合预期。进一步排查发现监控指标与实际情况不符，最终确认是由于JVM Full GC引起的CPU激增。通过分析堆内存快照，定位到四个大型`List<Map<String, String>>`对象占用了近900MB内存，这些对象由用户上传的Excel转换而来，导致内存膨胀。这些大对象在JVM中长时间驻留，容易触发Full GC。 为解决此问题，提出了两种方案： 1. 将数据存储于缓存而非JVM内存中； 2. 减少内存中对象的数据量，如删除无用字
游客otvqgjsxhwuvm
189 0
香吧香
|
监控 NoSQL Java
Spring Boot Actuator 使用和常用配置
Spring Boot Actuator 使用和常用配置
香吧香
1002 5
智物科技库
|
监控 JavaScript Java
JVM源码级别分析G1发生FullGC元凶的是什么
线上系统遭遇频繁Old GC问题，监控显示出现多次“to-space exhausted”日志，这表明垃圾回收过程中因年轻代 Survivor 区或老年代空间不足导致对象晋升失败。通过 JVM 源码分析，此问题源于对象转移至老年代失败时，JVM 无法找到足够的空间存放存活对象。进一步排查发现大对象分配占用了预留空间，加剧了空间不足的情况。使用 JFR 分析工具定位到定期报表序列化导致大量大对象生成，通过改用堆外内存进行序列化输出，最终解决了频繁 Old GC 问题。
智物科技库
466 0
蓝易云
|
8月前
|
XML Java 开发者
Spring底层架构核心概念解析
理解 Spring 框架的核心概念对于开发和维护 Spring 应用程序至关重要。IOC 和 AOP 是其两个关键特性，通过依赖注入和面向切面编程实现了高效的模块化和松耦合设计。Spring 容器管理着 Beans 的生命周期和配置，而核心模块为各种应用场景提供了丰富的功能支持。通过全面掌握这些核心概念，开发者可以更加高效地利用 Spring 框架开发企业级应用。
蓝易云
255 18