1.背景
开发的时候登录OSS控制台预发机器,发现Java进程CPU占用率其高,按道理预发机器只是内部开发及产品会使用,根本不可能占用这么大的资源,第一反应就是,进程在某个地方死循环了。
2.调查
猜测归猜测,还是要用事实说话。
第一步:top -Hp 15057 查看下进程中的线程资源占用情况
由上图可见,CPU时间片主要是被15393 这个线程给吃掉了, 所以目标锁定在 15393。
执行 printf "%x\n" 15393,计算出线程ID对应的16进制。
第二步:执行 sudo -u www jstack 15057,获取当前进程中各线程的调用栈
对比之前计算出来的二进制id:3c21,找到占用CPU资源最高的线程堆栈,如上图所示。
看样子是在LoguUtil的255行出了问题,赶紧定位到这一行看看:
这里写了一个死循环,并在255行调用了阻塞队列的poll(),很明显,方法调用错了,poll()在队列会空的时候会直接返回null,并不会阻塞等待,所以造成进程一直在这儿死循环。
那么为什么测试的时候没有发现呢?因为只要有日志,代码很难走到255行,之所以能发现这个问题,是因为我登录机器这段时间是在深夜,刚好没有日志。
3.验证
将代码修改提交部署后,在登录机器看看CPU占用情况:
此时Java进程的CPU占用已经恢复正常了。
4.总结
平时开发需求,除了验证基本的功能完整性之外,一定要注意对性能的影响,及时发现并解决问题。
来源 | 阿里云开发者公众号
作者 | 勉成