一次CPU占用过高事件的胡乱解决

1.起因

之前组里做了一个基于drools的业务逻辑校验程序，使用的是java语言。因为工作后一直就用C#，但是学校里教的都是java，用上了很久没用的java还是挺高兴的。做完，测试完，放到线上，回家。

我们的服务设定是每天早上5点定时跑的，到了第二天早上，手机就接到Zabbix的报警短信，我们的那台跑检验程序的机器CPU占用率超过80%,虽然我们之前Drools规则系统已经加入了很多业务，但是CPU占用过高这事从来没发生过，这锅看来必须自己背了。 

2.定位问题

到了公司，赶紧看看出了什么问题。重新启动程序，发现CPU占用率在10-70之间波动。查看日志可以发现CPU占用率高的时候代码正在查询Sql Server数据库。

我们数据库访问用到了iBatis，第一感觉是iBatis开了多线程消耗CPU，但是观察程序运行时的线程数并没有增多太多。想着用最新版本是不是可以解决，于是更新了iBatis库的版本。。。然而CPU占用率还是很高。

为了确定是不是Sql语句本身导致的CPU占用，我在Sql Server客户端里面试着运行了下程序的Sql语句，发现CPU占用就没超过20%过。。。

然后用JDBC执行了下访问数据库的语句，发现CPU占用根本不高，而且程序速度也变快了很多。。。 
似乎结论很明显了：辣鸡iBatis，速度慢还占CPU。。

于是我花了一早上时间把原来的iBatis查询数据库的语句全替换成了JDBC的方式，然后放上了服务器，运行。结果非常让人失望。。CPU依然占用很高。。。

下午做别的事情了，这件事就没管。第二天早上一来，发现程序报错了。gc overhead limit exceeded。 百度之，内存不足？按网上的方法，修改了JVM的启动参数，设置了JVM的最大内存，重新运行。这下不报错了，但是CPU占用高的问题还是存在。

觉得要好好查查哪里出问题了。就从网上下载了Process Explorer这么一个工具，用来分析每个线程的CPU占用。 
Process Explorer是Windows下的一个类似任务管理器的工具，但是除了能查询更多参数外，Process Explorer在这里最大的用处是能定位到每一个线程的CPU占用。简单介绍下用法： 

选择需要查看的进程，右键，选中Properties。然后选中Threads选项卡，就能看到当前进程的所有线程TID，以及占用CPU和CPU Cycles。这里有Start Address，不过这个地址基本不是人能看懂的【皱眉】。

运行程序，打开Process Explorer，终于发现了CPU占用率波动的原因。从Process Explorer的画面上能看到每隔一段时间，就有10多个线程的CPU占用率突然变高，到3%左右，这十几个线程同时占用CPU又同时消失，而且这几个线程的出现时各自的CPU占用率几乎一样。想到昨天的gc overhead limit exceeded报错，百度的结果大部分说的是内存不足，但是还发现有一种说法是GC时间过长而且回收内存过低，导致JVM认为你存在内存溢出。。。于是提前报Out of Memory异常。可以给JVM加上启动项取消这个提前退出机制，但是这么做治标不治本，所以没用。但是这几个线程让我怀疑到了GC上来。 
 
占用CPU的线程现在用Process Explorer可以看到了，距离真相就差找到线程对应的代码了。要怎么看线程对应的代码呢？Jdk有个自带工具叫JStack，使用命令 JStack -l [pid] > C：\1.txt把分析结果输入C:\1.txt。打开文件，搜索之前Process Explorer中看到的TID（JStack中tid是16进制记录的，记得用计算机转化为16进制）： 

具体用法还可以参考JStack和Process Explorer。查了几个占用CPU很高的线程，最终发现了罪魁祸首果然是Java的GC线程。

如何查看GC情况呢？在JVM虚拟机后加上参数-XX:+PrintGCDateStamps -XX:+PrintGCDetails，这样Java程序就会在控制台中打印出GC详情。发现部分GC时间很长，甚至达到9秒，没截图，从网上找了一段日志，看起来是这样的： 
2015-12-06T12:32:02.890+0800: 
[GC [PSYoungGen: 142833K->10728K(142848K)] 166113K->59145K(317952K), 0.0792023 secs] 
[Times: user=0.22 sys=0.00, real=0.08 secs] 。 
real=0.08 secs表示真实GC时间，PSYoungGen: 142833K->10728K(142848K) 中PSYoungGen表示这次回收是针对Young Generation对象的垃圾回收，142833K->10728K分别代表回收前和回收后的大小。

3.解决

看来是错怪了iBatis了。于是从减少GC入手，一开始尝试将程序中占用内存较多的对象转化为Static对象存储，企图阻止GC收集，结果并没有什么用。。。。又尝试设置iBatis的Ferch Size属性，控制每次获取数据库的行数，减少内存增长速度，CPU占用率稍有降低，但是还是不够。百度了很久，发现了一篇文章：成为Java GC专家（5）—Java性能调优原则 按照文章的说法，在JVM启动时加上参数 
-XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:+UseConcMarkSweepGC 
-XX:CMSInitiatingOccupancyFraction=75，网上有提到JVM提供了3种垃圾收集器，如果是长生命周期（老年代）对象较多时可以使用CMS收集器。 

实验证明主要是参数-XX:+UseConcMarkSweepGC起作用，添加上以后，CPU占用率终于保持在20%左右，更神奇的是内存占用都变小了。当然，垃圾回收时间减少了，程序速度都变快了不少。

要理解其中具体原因，看来还得了解下JAVA GC的工作原理了。。