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