一次生产环境CPU占用高的排查

Posted 2023-02-13 我从二院来

1. 项目背景

甲方是保密级别非常高的政府部门。所以我们全程拿不到任何测试数据，只能是自己模拟数据进行测试。
项目部署的时候，公司派了一人到甲方现场，在甲方客户全程监督下，进行部署，调试，导入数据等工作。因为前期看不到真实的数据，所以很多功能都是凭客户口述进行，到了现场难免发现问题。
这时需要改动代码重新打包部署，需要客户特制U盘需入密码才能传到内网。总之，非常麻烦。
如果有什么BUG，全靠同事口述。如果是功能性的什么BUG还好，沟通虽然困难，大体都能很快解决。

但是，对的，“但是”虽迟但到，同事在现场遇到一个所谓"很奇怪"的问题。当导入某一批文件的时候，程序就卡在那里不动了。

2. 技术背景

长话短说就是，通过页面批量上传文件，后端接到文件后会做一些word,pdf转换按页按段落提取文字，并通过消息队列kafka异步进行下一步处理：包括不限于语义分析通过算法提取出关键要素，以及要素之间的关联等等。
嗯，不涉及具体业务，不算涉密。

同事描述的现象包括：

• 1.程序卡住了
• 2.kafka报错了
• 3.算法返回500
• 4.重启了spring boot应用，kafka,算法服务都没法恢复。

以上是同事在现场用手机打字交流的一个简单复盘。非严格按照时间线来的。

2.1 程序卡住了

同事只给出了程序卡住的现象描述，没给能出具体的节点。我只能通过不停的加日志来确定具体卡在哪里。
最终确定卡在某个算法调用期间。

结合同事曾说过算法调用出了问题，看看算法问题。

2.2 算法问题

算法是我使用django封装了一个python web接口。具说http请求返回了500，那应该是web服务内部异常。
但是奇怪的是，同事说算法日志没有看到异常信息。

因为NLP涉及到vocab,如果有生僻字或者vocab文件里不包含的字符，可能会导致算法异常或者解析异常。

但同事反馈说没有相关的异常。

2.3 kafka报错了

这应该是一个乌龙。
我在spring kafkatemplate发送消息的时候打印了回调消息。

    * 向kafka发送doc相关信息
     * @param info
     */
    public void sendDocInfo(String info) 
        this.template.send(docTopic, info);
        ListenableFuture listenableFuture = this.template.send(docTopic, info);
        boolean bool = listenableFuture.isDone();
        log.info("kafka发送状态 :" + bool);
    

在某个算法调用期间一直卡住，超过了kafka默认的5分钟的限制，返回了false。
换句话说，这里的日志不能表明kafka出了问题。它只是程序卡住的一个连锁现象反映，远不是本质原因。

2.4 重启服务都没用

兜兜转转，打包上传到现场，客户再手动导入。时间一步步流逝。

听到同事说重启了spring boot应用，kafka,算法应用都没用以后，我一度有点懵逼了。
如果是某个线程一直空耗没释放，一定会导致CPU升高，（这里插一句，提过top jstack查看CPU高的线程的堆栈日志），但是重启应用肯定会释放的呀。

这怎么会重启了还是这样呢？

小半天就这么过了，下午5点客户就催下班了。又是羡慕体制内的一天。

3.重新确定方向

经过一晚的大脑放空，我觉得不能被零散的信息牵着鼻子走。
我觉得我应该放过多余信息，直捣黄龙。
程序卡住了？这种系统假死问题，第一反应肯定是查看CPU啊，有没有占用CPU高的进程，再查看应用里具体的是哪个线程在占用着cpu,再通过jstack找到具体的应用代码。

就算是最后不是这个问题，以上操作也是一个非新手程序员的基操啊。

而且，为什么重启应用后会重现卡住的现象？因为kafka啊。
kafka为了确保不丢消息。在生产端，集群，消费端都需要做出努力。当然，这其实不是kafka独有，任何消息队列都是相同的思路。
具体到kafka消费端，为保证不丢消息，至少保证在没有异常的情况下才做ack.
当程序假死的时候，没有执行ack操作，那么当程序重启的时候，kafka当然会去做重新拉取信息的动作。又造成程序假死。

这很合理，完全可以说得通。

当然这只是我上班路上的推测。

一大早，新的一天，一切清零。到公司，跟同事说了，他重启了程序，没有上传文件，通过后台日志，观察到kafka确实在消费之前的数据。

很好，验证得到证实，完美的开始。

接下来，就是通过top命令查看是否有CPU占用高的现象。

涉密项目哦，可不敢可没有截图哦。

同事说到有个进程占用CPU超过100%，从占用时间上推测，从重启过后就一直没释放。

非常好，验证了第2个猜想。

再通过 top -H -p pid命令得到应用内占用CPU高的具体线程。将线程ID转为十六进程，再通过jastck grep 线程码就可以定位到具体的代码。

具体的定位过程因为项目原因，不便不能展示过多，技术方面的细节参考我的另一篇文章( 【工作随手记】deaklock排查)

告诉同事重点查看带有自己公司包名的代码，很快就定位到了代码位置。

因为完全与业务无关，可以把代码放上来。

/**
 * 获取一个字符串和关键词，查找这个字符串出现的次数
 * @param str 原文
 * @param key 关键词
 * @return
 */
public static int getStringCount(String str, String key) 
    int count = 0;
    int index = 0;
    while ((index = str.indexOf(key)) != -1) 
        count++;
        str = str.substring(index + key.length());
    
    return count;

看到这个while我一瞬间就知道，症结找到了。

当传入的关键词为""空串时，直接就会陷入while死循环。这就是程序假死的本质原因。

4.总结

从一下午找不到重点，到第二天半小时解决问题。我也在思考，这中间的差异出了什么问题。

项目的特殊背景，是一个原因，但不是主要原因。身处这个行业，以后总要有这方面的需求和场景，不能每次都拿项目特殊性来背书和推脱。

我觉得以下几点是我从这件事当中学到的，在今后的工作的应该尽量避免或者学习的。

• 1.技术人应该相信自己的直觉。
• 2.沟通应该要有效率。要有目的。区分主次。
• 3.从纷繁的反馈中提取有效的信息，是一种能力且可锻炼。
• 4.保持清醒的大脑。否则，宁愿停下来。

苍茫之天涯，乃吾辈之所爱也；浩瀚之程序，亦吾之所爱也，然则何时而爱耶？必曰：先天下之忧而忧，后天下之爱而爱也！