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

Posted 我从二院来

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了一次生产环境CPU占用高的排查相关的知识,希望对你有一定的参考价值。

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.保持清醒的大脑。否则,宁愿停下来。

以上是关于一次生产环境CPU占用高的排查的主要内容,如果未能解决你的问题,请参考以下文章

一次java Cpu占用过高的排查

记一次线上机器CPU飙高的排查过程

Linux生产环境下---问题指标面试

记一次java程序占用cpu超高排查

SQLSERVER排查CPU占用高的情况

记一次JAVA进程导致Kubernetes节点CPU飙高的排查与解决