记录一次线上服务发生FullGC的原因

在2023年12月6日上午，我们团队内部收到一个线上问题反馈：第三方平台请求我们下单接口响应时间慢，影响用户下单体验。

下单接口RT时间超过4.5s

后面经过结合当时业务动作情况和阿里云AW MS应用监控情况，排查并定位出了具体原因。现以此篇文章回顾一下当时的排查过程。

首先从下单接口着手切入，假定下单接口所在服务为服务A。查看服务A下单接口的调用链路，检查下游服务接口耗时，发现服务B的某个查询接口耗时较长。

服务A依赖服务B某查询接口耗时超过2s

然后查看服务B查询接口queryXxxBaseInfo响应情况，发现响应时间非常慢，并且服务B存在频繁FullGC。

查看服务B应用事件，在相应时间点出现RT突增事件。

查看服务B接口queryXxxBaseInfo方法执行方法栈，从下图可看出该方法触发了forkjoin并行任务，ForkJoinTask.externalAwaitDone方法阻塞等待耗时约1.5s，占queryXxxBaseInfo方法总耗时达98%。

queryXxxBaseInfo方法在数据达到一定量级时会触发并行处理

基于上面监控情况可以得出由于某些原因导致服务B频繁发生FullGC，应用出现STW，服务性能下降，接口响应变慢。因此需要进一步排查服务B发生FullGC的真正原因。

接下来，结合当天业务动作情况，需要对大部分商户商品价格信息进行调整，系统发出了较多的价格变动消息，其中一个服务消费该消息，并需要将商户的最新信息重新推送给第三方平台。在排查代码逻辑后，发现推送业务逻辑中存在一个业务校验：判断该商户是否在第三方平台开放。在该业务校验中采取先查询出平台当前支持的所有商户的信息，于是请求了上述提到的服务B查询接口queryXxxBaseInfo，并且单次请求则请求大量商户信息（多达几千个商户），一个商户详细信息相当于一个大对象，一次性请求大量商户信息会创建大量对象，且处理大数据请求时耗时较久，创建的对象不能及时在YoungGC阶段回收掉，导致服务B整体堆内存不足，发生FullGC。随后检查了下单接口代码，恰巧也存在这个业务校验，受FullGC影响，下单接口响应变慢。

最后得出结论：上游服务存在并发请求服务B接口queryXxxBaseInfo的情况，且单次请求会请求大量数据，导致服务B频繁发生FullGC，服务出现卡顿，从而导致上游服务接口RT变高。

跟同事们沟通后，采取优化业务代码方案，降低单次请求数据量而又不改变原有的业务校验流程，又能有效规避queryXxxBaseInfo的并行处理。优化代码发布上线后，问题得到全面解决。

为模拟本次FullGC问题，我编写了一个demo。代码仓库https://gitee.com/ljxcolin/fullgc-demo.git，感兴趣的程序猿可以下载实践。

先看一下项目结构：

fullgc-demo-service-a和fullgc-demo-service-b均为SpringBoot应用，fullgc-demo-service-a模拟推送并请求查询，fullgc-demo-service-b模拟提供查询服务，具体看下面代码。

fullgc-demo-service-a的PushController代码

@RestController
public class PushController {

    private final PushService pushService;

    public PushController(PushService pushService) {
        this.pushService = pushService;
    }

    @PostMapping("/pushStore")
    private Result<Void> pushStore(@RequestParam("storeId") Long storeId) {
        return pushService.pushStore(storeId);
    }

}

fullgc-demo-service-a的PushService代码

@Service
public class PushService {

    private static final Logger log = LoggerFactory.getLogger(PushService.class);

    private static final Map<Integer, List<Long>> platformStoreMap = new ConcurrentHashMap<>();

    static {
        List<Long> storeIds = new ArrayList<>(3000);
        for (long storeId = 1; storeId <= 3000; storeId++) {
            storeIds.add(storeId);
        }
        platformStoreMap.put(1, storeIds);
    }

    @Resource
    private RestTemplate restTemplate;

    public Result<Void> pushStore(Long storeId) {
        log.info("开始推送店铺|storeId={}", storeId);
        // ... ... 一些业务处理

        // 请求服务b获取店铺信息
        Integer platformId = 1;
        List<Long> storeIds = platformStoreMap.get(platformId);
        StoreQueryDto queryDto = new StoreQueryDto();
        queryDto.setStoreIds(storeIds);
        // 使用restTemplate模拟服务间调用
        ResponseEntity<Result> responseEntity = restTemplate.postForEntity("http://localhost:8082/service-b/store/queryStoreDetail", queryDto, Result.class);
        log.info("响应状态码：{}", responseEntity.getStatusCodeValue());
        Result result = responseEntity.getBody();
        if (result != null) {
            log.info("响应结果：{}, {}", result.getCode(), result.getMessage());
        }

        // ... ... 一些业务处理
        log.info("结束推送店铺|storeId={}", storeId);
        return Result.success();
    }

}

fullgc-demo-service-b的StoreController代码

@RestController
@RequestMapping("/store")
public class StoreController {

    private final StoreService storeService;

    public StoreController(StoreService storeService) {
        this.storeService = storeService;
    }

    @PostMapping("/queryStoreDetail")
    public Result<List<StoreDetailInfoDto>> queryStoreDetail(@RequestBody StoreQueryDto queryDto) {
        return storeService.queryStoreDetail(queryDto);
    }

}

fullgc-demo-service-b的StoreService代码

@Service
public class StoreService {

    private static final Logger log = LoggerFactory.getLogger(StoreService.class);

    public Result<List<StoreDetailInfoDto>> queryStoreDetail(StoreQueryDto queryDto) {
        // 模拟查询基本信息
        List<StoreDetailInfoDto> storeDetailInfoDtos = getStoreDetail(queryDto);

        // 模拟查询其他详情信息
        int batchSize = 100;
        if (storeDetailInfoDtos.size() < batchSize) {
            // 直接串行查询其他详情信息
            fetchOtherDetail(storeDetailInfoDtos);
        } else {
            // 使用并行流查询其他详情信息
            Lists.partition(storeDetailInfoDtos, batchSize).parallelStream()
                    .forEach(this::fetchOtherDetail);
        }

        return Result.success(storeDetailInfoDtos);

    }

    private List<StoreDetailInfoDto> getStoreDetail(StoreQueryDto queryDto) {
        List<StoreDetailInfoDto> storeDetailInfoDtos = new LinkedList<>();
        if (queryDto.getStoreIds() != null && queryDto.getStoreIds().size() > 0) {
            for (Long storeId : queryDto.getStoreIds()) {
                StoreDetailInfoDto storeDetailInfoDto = new StoreDetailInfoDto();
                StoreBaseInfoDto storeBaseInfoDto = new StoreBaseInfoDto();
                storeBaseInfoDto.setStoreId(storeId);
                storeBaseInfoDto.setStoreName("店铺名称-" + storeId);
                storeBaseInfoDto.setProvince("广南省");
                storeBaseInfoDto.setCity("深海市");
                storeBaseInfoDto.setAddress("宝平大道金龙社区99巷10001号");
                storeDetailInfoDto.setBaseInfoDto(storeBaseInfoDto);
                storeDetailInfoDtos.add(storeDetailInfoDto);
            }
        }
        return storeDetailInfoDtos;
    }

    private void fetchOtherDetail(List<StoreDetailInfoDto> storeDetailInfoDtos) {
        // 模拟查询配置信息
        List<StoreConfigInfoDto> storeConfigInfoDtos = new ArrayList<>(storeDetailInfoDtos.size());
        for (StoreDetailInfoDto detailInfoDto : storeDetailInfoDtos) {
            StoreBaseInfoDto baseInfoDto = detailInfoDto.getBaseInfoDto();
            StoreConfigInfoDto configInfoDto = new StoreConfigInfoDto();
            configInfoDto.setStoreId(baseInfoDto.getStoreId());
            configInfoDto.setContacts("选经理");
            configInfoDto.setContactPhone("19999999999");
            configInfoDto.setCoverUrl("https://www.ljxcolin.com/store-cover-url.png");
            configInfoDto.setStar((int) (Math.random() * 5));
            storeConfigInfoDtos.add(configInfoDto);
        }

        // 模拟查询商品信息
        List<StoreGoodsInfoDto> storeGoodsInfoDtos = new ArrayList<>();
        for (StoreDetailInfoDto detailInfoDto : storeDetailInfoDtos) {
            StoreBaseInfoDto baseInfoDto = detailInfoDto.getBaseInfoDto();
            int goodsSize = (int) (Math.random() * 100);
            long goodsId = 0;
            for (int i = 0; i <= goodsSize; i++) {
                StoreGoodsInfoDto goodsInfoDto = new StoreGoodsInfoDto();
                goodsInfoDto.setStoreId(baseInfoDto.getStoreId());
                goodsInfoDto.setGoodsId(goodsId++);
                goodsInfoDto.setGoodsName("商品名称-" + goodsInfoDto.getGoodsId());
                goodsInfoDto.setGoodsPrice(BigDecimal.valueOf(Math.random() * 100).setScale(2, RoundingMode.HALF_UP));
                storeGoodsInfoDtos.add(goodsInfoDto);
            }
        }

        Map<Long, StoreConfigInfoDto> configInfoDtoMap = storeConfigInfoDtos.stream().collect(Collectors.toMap(StoreConfigInfoDto::getStoreId, Function.identity()));
        Map<Long, List<StoreGoodsInfoDto>> goodsInfoDtoMap = storeGoodsInfoDtos.stream().collect(Collectors.groupingBy(StoreGoodsInfoDto::getStoreId));

        for (StoreDetailInfoDto detailInfoDto : storeDetailInfoDtos) {
            StoreBaseInfoDto baseInfoDto = detailInfoDto.getBaseInfoDto();
            log.info("封装店铺[{}]详细信息", baseInfoDto.getStoreId());
            StoreConfigInfoDto configInfoDto = configInfoDtoMap.get(baseInfoDto.getStoreId());
            List<StoreGoodsInfoDto> goodsInfoDtos = goodsInfoDtoMap.get(baseInfoDto.getStoreId());
            detailInfoDto.setConfigInfoDto(configInfoDto);
            detailInfoDto.setGoodsInfoDtos(goodsInfoDtos);
        }

        // 模拟耗时
        try {
            TimeUnit.MILLISECONDS.sleep(1000L);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

}

模拟请求fullgc-demo-service-a的pushStore接口的测试类Tests代码

public class Tests {

    @Test
    public void testPushStore() {
        List<Thread> threads = new LinkedList<>();
        for (int i = 0; i < 50; i++) {
            Long storeId = i + 1L;
            Runnable runnable = () -> {
                Map<String, Object> paramMap = new HashMap<>();
                paramMap.put("storeId", storeId);
                String responseBody = HttpUtil.post("http://127.0.0.1:8081/service-a/pushStore", paramMap);
                System.out.println(Thread.currentThread().getName() + " ##### " + responseBody);
            };
            Thread t = new Thread(runnable, "test-thread-" + i);
            t.start();
            threads.add(t);
        }

        for (Thread t : threads) {
            try {
                t.join();
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

}

接下来进行模拟测试。先启动fullgc-demo-service-b服务，VM options如下图所示。新生代使用ParNew垃圾回收器，老年代使用CMS垃圾回收器。

 -Xms256m
 -Xmx256m
 -XX:+UseConcMarkSweepGC
 -XX:CMSInitiatingOccupancyFraction=80
 -XX:+PrintGCDetails
 -XX:+PrintGCDateStamps
 -Xloggc:./gc_%p.log
 -XX:+HeapDumpOnOutOfMemoryError
 -XX:HeapDumpPath=./

再启动fullgc-demo-service-a服务，VM options使用默认值。最后运行测试类testPushStore方法进行测试。

查看fullgc-demo-service-b服务的gc日志gc_pid27209.log，呈现如下。从2024-02-12T21:04:09开始，出现多次内存分配失败，并触发YoungGC。随后新生代对象不断晋升到老年代，老年代内存使用占比超过设定阈值80%（默认92%，147493K/174784K≈84%，大于80%），触发老年代GC即CMSGC。再之后由于CMS回收速度跟不上对象生成速度，出现并发模式失败（concurrent mode failure），从而触发了FullGC。

Java HotSpot(TM) 64-Bit Server VM (25.271-b09) for bsd-amd64 JRE (1.8.0_271-b09), built on Sep 16 2020 16:54:38 by "java_re" with gcc 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)
Memory: 4k page, physical 16777216k(274592k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:CMSInitiatingOccupancyFraction=80 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./ -XX:InitialHeapSize=268435456 -XX:+ManagementServer -XX:MaxHeapSize=268435456 -XX:MaxNewSize=89481216 -XX:MaxTenuringThreshold=6 -XX:NewSize=89481216 -XX:OldPLABSize=16 -XX:OldSize=178954240 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2024-02-12T21:01:53.129-0800: 0.919: [GC (Allocation Failure) 2024-02-12T21:01:53.129-0800: 0.919: [ParNew: 69952K->8559K(78656K), 0.0072919 secs] 69952K->8559K(253440K), 0.0075081 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
2024-02-12T21:01:53.825-0800: 1.615: [GC (Allocation Failure) 2024-02-12T21:01:53.825-0800: 1.615: [ParNew: 78511K->8093K(78656K), 0.0168232 secs] 78511K->11436K(253440K), 0.0169152 secs] [Times: user=0.05 sys=0.01, real=0.02 secs] 
2024-02-12T21:01:53.842-0800: 1.632: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3343K(174784K)] 12638K(253440K), 0.0008455 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:01:53.843-0800: 1.633: [CMS-concurrent-mark-start]
2024-02-12T21:01:53.846-0800: 1.636: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
2024-02-12T21:01:53.846-0800: 1.636: [CMS-concurrent-preclean-start]
2024-02-12T21:01:53.846-0800: 1.637: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:01:53.847-0800: 1.637: [GC (CMS Final Remark) [YG occupancy: 9294 K (78656 K)]2024-02-12T21:01:53.847-0800: 1.637: [Rescan (parallel) , 0.0007821 secs]2024-02-12T21:01:53.847-0800: 1.638: [weak refs processing, 0.0000333 secs]2024-02-12T21:01:53.848-0800: 1.638: [class unloading, 0.0015005 secs]2024-02-12T21:01:53.849-0800: 1.639: [scrub symbol table, 0.0022073 secs]2024-02-12T21:01:53.851-0800: 1.642: [scrub string table, 0.0002332 secs][1 CMS-remark: 3343K(174784K)] 12638K(253440K), 0.0052332 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-02-12T21:01:53.852-0800: 1.642: [CMS-concurrent-sweep-start]
2024-02-12T21:01:53.854-0800: 1.644: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2024-02-12T21:01:53.854-0800: 1.644: [CMS-concurrent-reset-start]
2024-02-12T21:01:53.855-0800: 1.645: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:01:54.548-0800: 2.338: [GC (Allocation Failure) 2024-02-12T21:01:54.548-0800: 2.338: [ParNew: 78045K->8703K(78656K), 0.0084791 secs] 81385K->15607K(253440K), 0.0085833 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2024-02-12T21:04:09.027-0800: 136.818: [GC (Allocation Failure) 2024-02-12T21:04:09.027-0800: 136.818: [ParNew: 78655K->8704K(78656K), 0.0456117 secs] 85559K->40546K(253440K), 0.0457682 secs] [Times: user=0.16 sys=0.03, real=0.05 secs] 
2024-02-12T21:04:09.177-0800: 136.968: [GC (Allocation Failure) 2024-02-12T21:04:09.177-0800: 136.968: [ParNew: 78656K->8704K(78656K), 0.0356650 secs] 110498K->64382K(253440K), 0.0358239 secs] [Times: user=0.16 sys=0.02, real=0.04 secs] 
2024-02-12T21:04:09.261-0800: 137.052: [GC (Allocation Failure) 2024-02-12T21:04:09.261-0800: 137.053: [ParNew: 78656K->8704K(78656K), 0.0333328 secs] 134334K->84911K(253440K), 0.0334673 secs] [Times: user=0.12 sys=0.01, real=0.03 secs] 
2024-02-12T21:04:10.427-0800: 138.219: [GC (Allocation Failure) 2024-02-12T21:04:10.427-0800: 138.219: [ParNew: 78656K->8704K(78656K), 0.0221618 secs] 154863K->95010K(253440K), 0.0222620 secs] [Times: user=0.06 sys=0.01, real=0.03 secs] 
2024-02-12T21:04:11.490-0800: 139.281: [GC (Allocation Failure) 2024-02-12T21:04:11.490-0800: 139.282: [ParNew: 78656K->8704K(78656K), 0.0239882 secs] 164962K->109305K(253440K), 0.0241693 secs] [Times: user=0.15 sys=0.02, real=0.02 secs] 
2024-02-12T21:04:12.545-0800: 140.337: [GC (Allocation Failure) 2024-02-12T21:04:12.545-0800: 140.337: [ParNew: 78656K->8704K(78656K), 0.0203017 secs] 179257K->124745K(253440K), 0.0204157 secs] [Times: user=0.11 sys=0.01, real=0.02 secs] 
2024-02-12T21:04:14.556-0800: 142.347: [GC (Allocation Failure) 2024-02-12T21:04:14.556-0800: 142.347: [ParNew: 78656K->8704K(78656K), 0.0171741 secs] 194697K->140550K(253440K), 0.0172875 secs] [Times: user=0.09 sys=0.01, real=0.02 secs] 
2024-02-12T21:04:16.462-0800: 144.254: [GC (Allocation Failure) 2024-02-12T21:04:16.462-0800: 144.254: [ParNew: 78656K->8704K(78656K), 0.0172820 secs] 210502K->156197K(253440K), 0.0174008 secs] [Times: user=0.10 sys=0.01, real=0.01 secs] 
2024-02-12T21:04:16.480-0800: 144.272: [GC (CMS Initial Mark) [1 CMS-initial-mark: 147493K(174784K)] 156269K(253440K), 0.0021772 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:16.482-0800: 144.274: [CMS-concurrent-mark-start]
2024-02-12T21:04:16.570-0800: 144.361: [CMS-concurrent-mark: 0.087/0.087 secs] [Times: user=0.19 sys=0.00, real=0.09 secs] 
2024-02-12T21:04:16.570-0800: 144.361: [CMS-concurrent-preclean-start]
2024-02-12T21:04:16.571-0800: 144.362: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:16.571-0800: 144.362: [CMS-concurrent-abortable-preclean-start]
2024-02-12T21:04:17.601-0800: 145.393: [GC (Allocation Failure) 2024-02-12T21:04:17.601-0800: 145.393: [ParNew: 78656K->8704K(78656K), 0.0187526 secs] 226149K->172558K(253440K), 0.0188592 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
2024-02-12T21:04:17.634-0800: 145.426: [CMS-concurrent-abortable-preclean: 0.432/1.063 secs] [Times: user=0.65 sys=0.02, real=1.06 secs] 
2024-02-12T21:04:17.635-0800: 145.426: [GC (CMS Final Remark) [YG occupancy: 20919 K (78656 K)]2024-02-12T21:04:17.635-0800: 145.426: [Rescan (parallel) , 0.0078240 secs]2024-02-12T21:04:17.643-0800: 145.434: [weak refs processing, 0.0001955 secs]2024-02-12T21:04:17.643-0800: 145.434: [class unloading, 0.0038861 secs]2024-02-12T21:04:17.647-0800: 145.438: [scrub symbol table, 0.0058059 secs]2024-02-12T21:04:17.653-0800: 145.444: [scrub string table, 0.0004242 secs][1 CMS-remark: 163854K(174784K)] 184774K(253440K), 0.0186017 secs] [Times: user=0.07 sys=0.00, real=0.02 secs] 
2024-02-12T21:04:17.653-0800: 145.445: [CMS-concurrent-sweep-start]
2024-02-12T21:04:17.713-0800: 145.505: [CMS-concurrent-sweep: 0.060/0.060 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 
2024-02-12T21:04:17.713-0800: 145.505: [CMS-concurrent-reset-start]
2024-02-12T21:04:17.714-0800: 145.505: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:19.554-0800: 147.346: [GC (Allocation Failure) 2024-02-12T21:04:19.554-0800: 147.346: [ParNew: 78656K->78656K(78656K), 0.0000175 secs]2024-02-12T21:04:19.554-0800: 147.346: [CMS: 159823K->174783K(174784K), 0.3378766 secs] 238479K->175401K(253440K), [Metaspace: 29681K->29681K(1077248K)], 0.3381820 secs] [Times: user=0.33 sys=0.01, real=0.34 secs] 
2024-02-12T21:04:19.893-0800: 147.685: [GC (CMS Initial Mark) [1 CMS-initial-mark: 174783K(174784K)] 175503K(253440K), 0.0008495 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:19.894-0800: 147.686: [CMS-concurrent-mark-start]
2024-02-12T21:04:20.005-0800: 147.797: [CMS-concurrent-mark: 0.111/0.111 secs] [Times: user=0.29 sys=0.00, real=0.11 secs] 
2024-02-12T21:04:20.006-0800: 147.797: [CMS-concurrent-preclean-start]
2024-02-12T21:04:20.120-0800: 147.912: [CMS-concurrent-preclean: 0.115/0.115 secs] [Times: user=0.11 sys=0.00, real=0.12 secs] 
2024-02-12T21:04:20.120-0800: 147.912: [CMS-concurrent-abortable-preclean-start]
2024-02-12T21:04:20.120-0800: 147.912: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:20.121-0800: 147.912: [GC (CMS Final Remark) [YG occupancy: 31006 K (78656 K)]2024-02-12T21:04:20.121-0800: 147.912: [Rescan (parallel) , 0.0150401 secs]2024-02-12T21:04:20.136-0800: 147.927: [weak refs processing, 0.0000629 secs]2024-02-12T21:04:20.136-0800: 147.928: [class unloading, 0.0025092 secs]2024-02-12T21:04:20.138-0800: 147.930: [scrub symbol table, 0.0042501 secs]2024-02-12T21:04:20.143-0800: 147.934: [scrub string table, 0.0003328 secs][1 CMS-remark: 174783K(174784K)] 205790K(253440K), 0.0224201 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
2024-02-12T21:04:20.143-0800: 147.935: [CMS-concurrent-sweep-start]
2024-02-12T21:04:20.210-0800: 148.002: [CMS-concurrent-sweep: 0.067/0.067 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
2024-02-12T21:04:20.210-0800: 148.002: [CMS-concurrent-reset-start]
2024-02-12T21:04:20.210-0800: 148.002: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:21.479-0800: 149.271: [GC (Allocation Failure) 2024-02-12T21:04:21.479-0800: 149.271: [ParNew: 78655K->78655K(78656K), 0.0000210 secs]2024-02-12T21:04:21.479-0800: 149.271: [CMS: 174783K->174784K(174784K), 0.3554896 secs] 253439K->193008K(253440K), [Metaspace: 29504K->29504K(1077248K)], 0.3556368 secs] [Times: user=0.36 sys=0.00, real=0.36 secs] 
2024-02-12T21:04:21.835-0800: 149.627: [GC (CMS Initial Mark) [1 CMS-initial-mark: 174784K(174784K)] 193101K(253440K), 0.0091007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-02-12T21:04:21.845-0800: 149.636: [CMS-concurrent-mark-start]
2024-02-12T21:04:21.957-0800: 149.749: [CMS-concurrent-mark: 0.112/0.113 secs] [Times: user=0.30 sys=0.00, real=0.11 secs] 
2024-02-12T21:04:21.957-0800: 149.749: [CMS-concurrent-preclean-start]
2024-02-12T21:04:22.090-0800: 149.881: [CMS-concurrent-preclean: 0.132/0.132 secs] [Times: user=0.29 sys=0.02, real=0.14 secs] 
2024-02-12T21:04:22.090-0800: 149.882: [CMS-concurrent-abortable-preclean-start]
2024-02-12T21:04:22.090-0800: 149.882: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:22.090-0800: 149.882: [GC (CMS Final Remark) [YG occupancy: 72558 K (78656 K)]2024-02-12T21:04:22.090-0800: 149.882: [Rescan (parallel) , 0.0156981 secs]2024-02-12T21:04:22.106-0800: 149.898: [weak refs processing, 0.0000538 secs]2024-02-12T21:04:22.106-0800: 149.898: [class unloading, 0.0026793 secs]2024-02-12T21:04:22.109-0800: 149.900: [scrub symbol table, 0.0039837 secs]2024-02-12T21:04:22.113-0800: 149.904: [scrub string table, 0.0003716 secs][1 CMS-remark: 174784K(174784K)] 247342K(253440K), 0.0230108 secs] [Times: user=0.11 sys=0.00, real=0.02 secs] 
2024-02-12T21:04:22.113-0800: 149.905: [CMS-concurrent-sweep-start]
2024-02-12T21:04:22.182-0800: 149.974: [Full GC (Allocation Failure) 2024-02-12T21:04:22.183-0800: 149.974: [CMS2024-02-12T21:04:22.185-0800: 149.977: [CMS-concurrent-sweep: 0.071/0.072 secs] [Times: user=0.13 sys=0.01, real=0.07 secs] 
 (concurrent mode failure): 174783K->174783K(174784K), 0.3695030 secs] 253439K->207430K(253440K), [Metaspace: 29995K->29995K(1077248K)], 0.3696229 secs] [Times: user=0.36 sys=0.00, real=0.37 secs] 
2024-02-12T21:04:23.004-0800: 150.796: [Full GC (Allocation Failure) 2024-02-12T21:04:23.004-0800: 150.796: [CMS: 174783K->174784K(174784K), 0.3504007 secs] 253439K->189885K(253440K), [Metaspace: 30012K->30012K(1077248K)], 0.3505216 secs] [Times: user=0.35 sys=0.00, real=0.35 secs] 
2024-02-12T21:04:23.355-0800: 151.147: [GC (CMS Initial Mark) [1 CMS-initial-mark: 174784K(174784K)] 190019K(253440K), 0.0084549 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2024-02-12T21:04:23.364-0800: 151.156: [CMS-concurrent-mark-start]
2024-02-12T21:04:23.473-0800: 151.264: [CMS-concurrent-mark: 0.109/0.109 secs] [Times: user=0.22 sys=0.01, real=0.11 secs] 
2024-02-12T21:04:23.473-0800: 151.265: [CMS-concurrent-preclean-start]
2024-02-12T21:04:23.589-0800: 151.381: [CMS-concurrent-preclean: 0.116/0.116 secs] [Times: user=0.12 sys=0.00, real=0.11 secs] 
2024-02-12T21:04:23.589-0800: 151.381: [CMS-concurrent-abortable-preclean-start]
2024-02-12T21:04:23.589-0800: 151.381: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2024-02-12T21:04:23.590-0800: 151.381: [GC (CMS Final Remark) [YG occupancy: 21709 K (78656 K)]2024-02-12T21:04:23.590-0800: 151.381: [Rescan (parallel) , 0.0120625 secs]2024-02-12T21:04:23.602-0800: 151.394: [weak refs processing, 0.0000669 secs]2024-02-12T21:04:23.602-0800: 151.394: [class unloading, 0.0029439 secs]2024-02-12T21:04:23.605-0800: 151.397: [scrub symbol table, 0.0054266 secs]2024-02-12T21:04:23.610-0800: 151.402: [scrub string table, 0.0005766 secs][1 CMS-remark: 174784K(174784K)] 196493K(253440K), 0.0213537 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 
2024-02-12T21:04:23.611-0800: 151.403: [CMS-concurrent-sweep-start]
2024-02-12T21:04:23.680-0800: 151.472: [CMS-concurrent-sweep: 0.069/0.069 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
2024-02-12T21:04:23.680-0800: 151.472: [CMS-concurrent-reset-start]

使用 jstat -gcutil 27209 1000 命令查看fullgc-demo-service-b服务的gc情况，可以看出YoungGC次数不断增加，FullGC次数也是迅猛增加。

fullgc-demo-service-b服务由于堆内存不足，发生OOM。使用JProfile工具查看堆内存dump文件java_pid27209.hprof文件，可以看到存在大量的StoreDetailInfoDto和StoreGoodsInfoDto对象，存在大量LinkedList大对象。

本次文章分享到此结束，如果你喜欢我的文章，欢迎点赞收藏。