最近在测试一个用java语言实现的数据采集接口时发现,接口一旦运行起来,CPU利用率瞬间飙升到85%-95%,一旦停止就恢复到40%以下,这让我不得不面对以前从未关注过的程序性能问题。
在硬着头皮查找资料定位错误修正bug的过程中参考了下面两篇文章:
windows下揪出java程序占用cpu很高的线程 并找到问题代码 死循环线程代码:http://blog.csdn.net/hexin373/article/details/8846919
java程序cpu占用过高问题分析:http://www.tuicool.com/articles/ZRzmAvZ(这篇文章中的图片显示不了)
最初想通过java自带的jconsole和jvisualvm来调试,但发现jconsole只能知道应用整体情况,不能定位问题,而jvisualvm最多查找到类,
如果所示,但不能更详细的进行定位。于是参考了上面两篇文章一步步实现了最终目的。
一、查找进程
查找问题进程比较简单,因为问题集中在CPU资源占用过高,那么我们查找进程时只需关注CPU。方法有两种:
1、查看Windows任务管理器
打开Windows任务管理器,查看——>选择列,勾选PID,然后查看进程项,并让其按照CPU列排序如图,找到 javaw.exe进程,其PID是9272。
2、利用jvisualvm工具
打开工具,然后启动应用,在Applications面板中即可看到应用所在进程的PID9272。
需要注意的是该工具并不能定位到线程。
查找到进程以后,将该进程的信息保存到本地,在cmd命令窗口中执行命令:jstack 9272 > C:\test\cdf.log,该命令的作用是将PID为9272的进程信息保存在本地C:\test\cdf.log文件中。
二、查找线程
根据进程查找线程,也有两种方法。
1、使用window自带命令pslist
首先确认系统是否安装了pslist命令程序,如果命令不识别即没有安装,则上微软官方网址http://technet.microsoft.com/en-us/sysinternals/bb896682.aspx下载,下载完将其解压到C:\Windows\System32路径下即可使用。
在cmd命令窗口中执行命令:pslist -dmx 9272,该命令的作用是罗列属于9272进程的线程信息。
通过该命令可以看到TID为9368和12484的线程占用资源最多。这样就基本确定了线程。
2、利用微软提供的Process Explorer工具
一般在windows下只能查看进程的CPU占用率,想要查看线程的CPU占用率可以通过该工具。下载地址是:http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx
下载后运行起来,找到PID为9272的进程
右键点击Properties...选项,看到如下信息:
可以看到占用CPU最多的也是TID为9368和12484的两个线程。
三、问题定位
问题定位需要以下步骤:
1、将线程TID转换为十六进制
因为通过jstack工具导出的信息中线程TID是十六进制的,所以我们首先转换进制,这里通过系统自带的计算器进行转换。
记录下2498这个数字。
2、在jstack工具导出的cdf.log中查找“2498”
通过Notepad++工具打开该文档,搜索到如下信息,可以看到问题定位到了MQStart.java:174。
去程序中需找该代码:
同理,对于TID=12484的线程也如同以上步骤进行查找,找到了170行代码。
由此基本可判断问题就出在了该段代码上。
四、修复bug
1、查找原因
通过以上步骤已经定位到了代码片段,但是这段代码看上去没什么错误,查找资料说很多情况是进入死循环了,但是这里确定不会死循环。思路似乎进入了死胡同。
无奈之下我将170行的if内的代码段全注释掉了,发现CPU依然飙高,这说明并不是这几行代码的错误,然后我if内做了一个输出操作,发现程序快速的不间断的进行输出。
====》
看到这个结果我突然醒悟,这段代码虽然没有进入死循环,但是循环内的代码并不复杂,而且没必要如此频繁的进行检查操作,这中间应该停歇一下。
2、修改方法
根据以上分析,我修改了这段代码:
再次运行测试发现CPU维持在50%以内。