CPU飚高案例

问题描述

某天下午突然收到大量的企业微信告警提示CPU超阈值以及慢接口告警.半个小时内,很多客户反馈小程序,APP各种系统异常

应急过程

首先进行初步的分析以及保留现场相关信息,确认初步的恢复系统可用方案(进行分工)

对应服务器节点查看cpu高的是哪些进程(top命令,查看监控等确认)
初步分析原因
确定是java进程导致,大多是2种情况.
1. 频繁gc
  使用jdk自带工具查看gc情况: jstat gc $pid 1000 -1 或者使用arthas查看
2. 死循环(长时间循环)
确认到对应进程有频繁gc情况.从线上dump内存快照和线程快照.使用MAT,TMDA等工具初步分析
为优先恢复系统可用先采取临时方案
确认到近期无版本变更,先紧急调整JVM启动参数,堆内存由原来的2G调整为3G
发现很快又出现CPU飚高情况
通过分析内存快照,线程快照,日志,监控数据等,追踪发现是由于运营人员进行多条配置触发了首页弹窗广告接口的历史遗留bug导致.优先迅速下线了该功能(代码临时写死接口返回空)
系统恢复正常

原因分析

弹窗广告配置分多种类型,所有商户/指定商户集合等类型.由于当时类型无代理商维度,因此当天运营人员导出60个左右代理商的商户列表,进行了多条弹窗广告的配置.每个代理商的商户列表数量大概在5K-2W个左右.平均1W
首页弹窗广告列表接口存在历史遗留bug.(具体可以看下面的复现过程)
在匹配商户的处理上,采取了获取所有广告配置,并获取对应广告的商户list匹配当前商户的不合理处理逻辑.每次接口要进行约60*1W=60W的数据过滤.且由于首页接口qps较高,近1000/s.导致内存消耗急剧增加,进而导致一系列问题.

复现过程

问题代码大致代码如下(本地模拟)

/**
 * 获取首页配置项列表(弹窗/banner广告等)
 */
@GetMapping("/getConfigList")
public Object getConfigList(@RequestParam("merchantId") String merchantId) {
    log.info("getConfigList start,merchantId->{}", merchantId);
    // 获取所有在有效期内的配置项列表
    List<ZcjConfig> configList = zcjConfigMapper.listEnable(new Date());
    List<ZcjConfig> result = new ArrayList<>();
    for (ZcjConfig config : configList) {
        if ("MERCHANT_LIST".equals(config.getEnableType())) { // 生效类型为指定商户列表的需要匹配商户
            List<ZcjConfigMerchant> configMerchantList = zcjConfigMerchantMapper.listByConfigId(config.getId());
            boolean containMerchant = configMerchantList.stream().anyMatch(p -> merchantId.equals(p.getMerchantId()));
            if (containMerchant) {
                result.add(config);
            }
        } else {
            result.add(config);
        }
    }
    log.info("getConfigList end,result->{}", JSON.toJSONString(result));
    return result;
}

对应进程28518 cpu占用率达到168%左右
可以通过 jps -lv | grep 28518 或者 ps -ef | grep 28518 查看对应进程对应的项目

image.png

对应进程存在频繁的gc

image.png

使用arthas也可以查看到频繁的gc以及gc线程占用cpu率高
使用top -Hp $pid也可以

image.png

arthas查看cpu占用率高的线程栈信息

image.png

应用日志出现OOM

image.png

MAT分析可以分析到大量的mybatis相关实例数据

image.png

查看线程栈详情可以定位到业务代码内容

image.png

定位代码,并结合应用日志,可以看到接口多次循环查表获取列表且返回结果集太大(线上更大)

image.png

事后改进措施

修复了代码bug.直接使用mysql匹配商户号方式优化代码处理逻辑.类似逻辑如下

SELECT 
  t.* 
from 
  (
    select 
      * 
    from 
      zcj_config 
    WHERE 
      start_time <= '2023-02-01 15:00:00' 
      AND end_time >= '2023-02-01 15:00:00' 
  ) AS t 
WHERE 
  case when t.enable_type = 'MERCHANT_LIST' then exists (
    select 
      1 
    from 
      zcj_config_merchant zcm 
    where 
      zcm.config_id = t.id 
      and zcm.merchant_id = 'merchant_10013'
  ) ELSE 1 = 1 end

优先进行指定代理商列表类型的需求的开发.避免类似匹配代理商需要设置多条商户广告配置的操作
增加了redis缓存.减少对DB的访问
调整应用JVM大小,2G扩大到3G
该代码处理逻辑属于比较低级的错误.也进一步规范了相关的代码规范以及开发流程