1.问题描述

• 7月4号,18:53分,值班时,WMS-SEVICE出现服务负载飙高的告警。

• 自动生成的Dump

2.问题分析排查过程:

• 看下"grafna"的服务监控，如下图，在18:50～18:55分这段时间内，确实服务CUP很高。

 为什么这么高啊？有大的网络IO操作吗？继续排查。

• 分析jstack文件
• 打开jstack文件，搜索"com.pupu",发现是截图所示的代码可能导致的这个问题

 疑问：看这个方法名是做更新操作的,为什么一个更新操作会导致服务CPU飙升啊？

• 打开idea，找到上面截图中所示的代码处。OMG。。。这。。。

•  他把这个更新操作放到了这个for循环中了。

这个updateCapacityConfig下面又有查询库操作

 List<ReserveReceivingCapacityConfig> reserveReceivingCapacityConfigs = reserveReceivingCapacityConfigMapper.selectList(query);

这个for循环中对象集合大小是89条，所以for循环会执行89次。

 而他把更新操作写在for代码里面,那意味着，每调用1次这个接口,他的更新方法会执行89次，而他的每个更新方法里面又有查询操作，那也就意味着这个查询操作也会执行89次。所以我们才看到会有很多查询对象产生(ReserveReceivingCapacityConfig)

下面是这个更新方法,这个更新方法有查询和更新操作

@Transactional(rollbackFor = Exception.class)
    public Integer updateCapacityConfig(List<ReserveReceivingCapacityConfigPO> pos) {
        if (CollectionUtils.isEmpty(pos)) {
            return 0;
        }
        List<ReserveReceivingCapacityConfig> poReserveReceivingCapacityConfigs = ConverterUtil.convert(pos, ReserveReceivingCapacityConfig.class);
        List<String> storeIds = poReserveReceivingCapacityConfigs.stream().map(ReserveReceivingCapacityConfig::getStoreId).distinct().collect(Collectors.toList());
        List<Integer> dates = poReserveReceivingCapacityConfigs.stream().map(ReserveReceivingCapacityConfig::getConfigDate).distinct().sorted().collect(Collectors.toList());

        LambdaQueryWrapper<ReserveReceivingCapacityConfig> query = Wrappers.lambdaQuery();
        query.eq(ReserveReceivingCapacityConfig :: getHasDeleted,false);
        query.in(ReserveReceivingCapacityConfig :: getStoreId,storeIds);
        query.between(ReserveReceivingCapacityConfig :: getConfigDate,dates.get(0),dates.get(dates.size() - 1));
        List<ReserveReceivingCapacityConfig> reserveReceivingCapacityConfigs = reserveReceivingCapacityConfigMapper.selectList(query);

        Iterator<ReserveReceivingCapacityConfig> iterator = poReserveReceivingCapacityConfigs.iterator();
        List<Long> removeIds = Lists.newArrayList();

        while (iterator.hasNext()) {
            ReserveReceivingCapacityConfig po = iterator.next();
            List<ReserveReceivingCapacityConfig> list = reserveReceivingCapacityConfigs.stream().filter(r -> r.getStoreId().equals(po.getStoreId()) &&
                    r.getConfigDate().equals(po.getConfigDate()) &&
                    r.getConfigHour().equals(po.getConfigHour()))
                    .collect(Collectors.toList());
            if (CollectionUtils.isNotEmpty(list)) {
                // 如果完全相同则不更新
                List<ReserveReceivingCapacityConfig> removes = list.stream().filter(r ->  r.getSkuCount().equals(po.getSkuCount()) && r.getProductCount().equals(po.getProductCount())).collect(Collectors.toList());
                if (CollectionUtils.isNotEmpty(removes)) {
                    iterator.remove();
                } else {
                    // 如果配置发生变化，则移除旧的保存新的
                    removeIds.addAll(list.stream().map(ReserveReceivingCapacityConfig::getId).distinct().collect(Collectors.toList()));
                }
            }
        }
        if (CollectionUtils.isNotEmpty(removeIds)) {
            log.warn("更新预约容量配置：removeIds = {}", JSONObject.toJSONString(removeIds));
            LambdaUpdateWrapper<ReserveReceivingCapacityConfig> updateWrapper = Wrappers.lambdaUpdate();
            updateWrapper
                    .in(ReserveReceivingCapacityConfig::getId, removeIds)
                    .set(ReserveReceivingCapacityConfig::getHasDeleted, true)
                    .set(ReserveReceivingCapacityConfig::getTimeUpdate,System.currentTimeMillis());
            reserveReceivingCapacityConfigMapper.update(updateWrapper);
        }
        if (CollectionUtils.isNotEmpty(poReserveReceivingCapacityConfigs)) {
            log.warn("更新预约容量配置：pos = {}", JSONObject.toJSONString(poReserveReceivingCapacityConfigs));
            return reserveReceivingCapacityConfigMapper.insertBatchSomeColumn(poReserveReceivingCapacityConfigs);
        }
        return 0;
    }

分析链路

• 看下他的链路。Owl应用性能监控显示，他执行了很多次数据库操作

疑问：既然执行了很多次数据库操作，那数据库DB监控上应该会有所体现吧。

数据库DB监控

• 看下数据库DB监控：证明这段时间“reservecapacityconfigs”这个表，确实有大量的数据库操作，其实这个对数据库也有很大的影响，并发量不大，如果并发量很高，数据库可能就直接gg了。

jmap文件

• 再看看jmap文件：产生了很多新的对象（ReserveReceivingCapacityConfig），为什么会产生很多对象？

因为这个updateCapacityConfig下面又有查询库操作

 List<ReserveReceivingCapacityConfig> reserveReceivingCapacityConfigs = reserveReceivingCapacityConfigMapper.selectList(query);

他的每个更新方法里面又有查询操作，那也就意味着这个查询操作也会执行89次。所以我们才看到会有很多查询对象产生(ReserveReceivingCapacityConfig)。

问题定位

• 所以：经过上面的这些排查，大概可以确定是这个update方法引起的。因为在for循环中执行了大量的数据库查询和更新操作，导致系统服务CPU飙升.这个更新接口耗时600s+.

调用入口

• 定时任务定时执行的。刚上线,所以先手动执行了1次。
• 

问题处理

• 停掉该接口对应的定时任务

处理结果

• 1.确认对业务没有影响，新建的表，新写的接口，业务还没有开始使用
• 2.第二天，优化后发版上线
• 3.生产问题复盘