记一次加锁导致ECS服务器CPU飙高的处理

前言

此前，我曾在《对几次通宵加班发版的复盘和思考》文中，表达过"每一次版本上线都应该像火箭发射一样严肃"的观点。与此同时，我也分析其中的原因并提出相应的解决方案。

我坚信，那篇文章中的措施和方案已经覆盖发版中遭遇的大部分场景。

尽管我们总是保持对技术的敬畏之心，每次发版也会验证的比较充分，仍然会有一些相对不太容易预知的事情发生。

所以,我将"火箭发射"观点改成了"每一次版本的上线都应该像火箭发射一样严肃，同时还需要准备一些预案"。

火线告警，CPU飚了

在多年的职业历练中，我养成了一个习惯——每次执行完发版任务的第二天，都会积极关注公司相关业务群的动向，并尽可能早的到公司。

这一天，和往常一样，我在早高峰的路上奋力前行，突然群里闪现出一条业务方发出的消息。

随即便是更多的业务对接群开始炸锅。

前段时间因为数据库性能问题，已经出现了几次线上宕机的情况，被用户吐槽。(为啥出现性能问题，此处省略若干字，后续有机会再娓娓道来)。

所以，每次今天再次遇到这样的问题，我们总是显得很被动。

我和业务团队的同事一边安抚用户的情绪，一边快马加鞭奔赴公司。

火速赶到公司之后,查看了报警日志，发现部署该业务接口的ecs CPU飙高了...

当机立断，回滚到上一版本。

大约一分钟之后，我们验证了可用性，并查看ecs和数据库各项指标，正常。

于是大家一一回复了用户群，对接群终于安静了。

猜测：分布式锁是罪魁祸

代码回滚之后一切变得正常，我们可以断定此次线上问题的一定是和昨晚的发版有关。

但是，是哪个功能或者那句代码引发了ecs cpu标高呢？

第一时间闪现在脑海里面的就是“一键已读”功能。
该功能的代码大致如下(已脱敏):


@Override
public void oneKeyRead(OneKeyReadBo bo) {
    //...

    //1. 拉取的未读的会话(群聊)
    List<Long> unReadChatIds = listUnReadChatIds(loginUser.getUserId());
    if (CollectionUtil.isEmpty(unReadChatIds)) {
        log.info("当前用户没有未读会话!");
        return;

    //2. 循环处理单个群的消息已读
    CompletableFuture.runAsync(
                    () -> {
                        processOneKeyReadChats(realUnReadChatIds, loginUser);
                    })
            .exceptionally(
                    error -> {
                        log.error("批量处理未读的群会话异常：" + error, error);
                        return null;
                    });
}


@Resource
private Executor taskExecutor;
private void processOneKeyReadChats(List<Long> realUnReadChatIds, User loginUser) {
    //循环处理单个群的消息已读
    for (Long groupChatId : realUnReadChatIds) {
        OneKeyReadMessageBo oneKeyReadMessageBo=new OneKeyReadMessageBo();
        //...省略一些代码
        oneKeyReadMessage(oneKeyReadMessageBo);
    }
}

/**
 * 单独处理一个群的消息已读
*/
private void oneKeyReadMessage(OneKeyReadMessageBo bo) {
    // 批量已读，按会话加锁
    String lockCacheKey = StrUtil.format("xxx:lock:{}:{}", bo.getUserId(), bo.getChatId());

    RLock lock = redissonClient.getLock(lockCacheKey);

    boolean success = false;
    try {
        success = lock.tryLock(10, TimeUnit.SECONDS);
    } catch (InterruptedException ignored) {
    }

    if (!success) {
        log.info(StrUtil.format("用户: {}, 消息: {}, 消息一键已读失败", bo.getUserId(), bo.getChatId()));
        throw new BizException("消息已读失败");
    }

    try {
         //1. ack 已读
         //...省略若干代码

         //2.chatmember已读
        //...省略若干代码

        //3.groupMsg已读
         //...省略若干代码
    } finally {
        lock.unlock();
    }
}

从上面的代码可以看出来，循环的最底层使用了分布式锁，且锁的时长是10s。

综上可以推断, ecs cpu爆高是底层消息处理加锁导致。

代码重构，星夜上线

过去我们总是对旧项目中的“老代码”嗤之以鼻。回头看自己写过的代码，难免有点"时候诸葛亮"的意思。

在这次的版本中，为了节省时间，从项目中别处复用了处理groupMsg的代码(复制粘贴确实很爽)。

但是，忽略了那个加锁的方法在单个会话的处理是适合的，却不适合大批量的处理。

于是对代码进行重构。

主要是如下几个改进：

处理未读会话提前，批量并使用同步的方式执行，后续流程异步处理。
这样做其实是为了快速相应前端，且前端立马刷新列表，让用户能够感知到群会话的未读数已经清除。
将unReadChatIds分批处理，每次最大处理1000个。防止单次处理的未读会话过大，最终到unReadMsg上消息处理量控制在一万以内。(Mysql in 的数量进行控制)。
消息未读数处理取消锁。

大致代码如下:


 @Override
    public void oneKeyRead(OneKeyReadBo bo) {


        //1. 拉取的未读的会话(群聊)
        List<Long> unReadChatIds = listMyUnReadChatIds(loginUser.getUserId(), bo.getBeginSendTime(), bo.getEndSendTime());
        if (CollectionUtil.isEmpty(unReadChatIds)) {
            log.info("当前用户没有未读会话!");
            return;
        }

        // 同步处理clear notify
        batchClearUnreadCount(unReadChatIds, loginUser.getUserId());

        //2. ack+groupMsg已读
        CompletableFuture.runAsync(
                () -> {
                    processOneKeyReadChats(unReadChatIds, loginUser);
                })
                .exceptionally(
                        error -> {
                            log.error("批量处理未读的群会话异常：" + error, error);
                            return null;
                        });
    }

    private void processOneKeyReadChats(List<Long> unReadChatIds, User loginUser) {
        //批处理
        int total = unReadChatIds.size();
        int pageSize = 1000;

        if (total > pageSize) {
            RAMPager<Long> pager = new RAMPager(unReadChatIds, pageSize);
            System.out.println("unReadChat总页数是: " + pager.getPageCount());
            Iterator<List<Long>> iterator = pager.iterator();
            while (iterator.hasNext()) {
                List<Long> curUnReadChatIds = iterator.next();
                if (CollectionUtil.isEmpty(curUnReadChatIds)) {
                    continue;
                }
                batchReadMessage(curUnReadChatIds, loginUser);
            }
        } else {
            batchReadMessage(unReadChatIds, loginUser);
        }
    }


    /**
     * 批量处理消息已读
     */
    private void batchReadMessage(List<Long> unReadChatIds, User loginUser) {

        try {
            //1. 批量ack 已读
            //...省略若干代码

            //2. groupMsg已读
            //...省略若干代码

        } catch (Exception ex) {
            log.error(StrUtil.format("batchReadMessage 异常,error:{}", ex.getMessage()));
        }
    }

下班之后，火速上线。

防患未然，功能可开关

尽管从理论上我已经推断出这个锁是引发ecs cpu爆高的主要因素。但是，内心依然是忐忑的。

比如，这样改造之后，到底能有多大的优化下效果？是否能够抗住明天的早高峰？
如果CPU再次飙高怎么办？

看得出来，这个功能上线之后确实受到了客户的青睐，所以能否抗住明天的早高峰，值得思考。

思考再三，为了能够在线上遇到问题时，不用发版就能快速处理，我决定临时给这个功能增加了一个开关。

这样，当生产环境开始报警的时候，我就可以快速地关闭该功能。

办法虽笨，但是道理很简单，非常适合这样的场景。

高度戒备，应对早高峰

保持系统的稳定性几乎是IT从业者的共识。

尽管我们已经做了代码重构，增加功能开关等工作，心里依旧是忐忑的。

第二天一大早我就来到公司。随时盯着各项监控指标，并等待早高峰的来临。

从9:00开始，已经用户开始使用我们的"一键已读"功能，但是服务器CPU使用率没有飙升，也没有报警。

观察了一下数据库的CPU使用率，逐渐开始走高并接近60%。

可以证明我们的代码重构是生效了的，这一点是值得欣慰的。
压力给到了mysql数据库，这是预料之中的，但是如果峰值超过90%，大概率会引发我们的系统崩溃。

我几乎每5s刷新一次数据库使用率这个指标，到了09:32,数据库使用率超过了98%,并且大约持续了1min,仍然在高位，系统已经游走在崩溃的边缘。

我迅速关闭了这个"一键已读"功能。

然后，数据库CPU使用率随即骤降，回归到20%~40%的水平。

可能，您不太理解我为啥如此关注这个指标？

下图是我们系统正常情况下的数据库使用率，基本维持在30%以下。

实时调整方案，稳了

那是什么原因导致数据库cpu突然飙高呢？

经过排查日志，发现有人选择近一个月的会话进行处理。

一个月的未读会话数量可能超过5000，下沉到群消息的未读数量，预计会在1w以上。

而群消息表的体量大概在2kw左右，这意味着要在这个大表里面in接近1w个参数。

连续排查发现，凡是选择一个月时间段的请求，数据库cpu都会立马飙升至60%以上。

权衡再三，我们立马将用户可选择的时长控制在一周以内(前端控制)。

再次开启功能，系统各项指标平稳且维持在合理范围。

至此，对该功能的处理终于完美收官了。

结语

在多年的职场洗礼之后，逐渐认识到技术并非孤立存在的。

或许对于大众而言所谓的"技术好"，不是单纯的卖弄技术，而是能够针对灵活多变的场景，恰到好处的运用技术。

活到老，学到老。

这里笔者只根据个人多年的工作经验,一点点思考和分享,抛砖引玉,欢迎大家怕批评和斧正。

参考

《对几次通宵加班发版的复盘和思考》

戎码一生