记一次线上CPU超高的排查过程

最近发现公司一个主机的CPU每隔几天就飚上去，导致机器上部署的服务不可用。

top
显示进程18781占用CPU超过190%（主机是双核）。
top -Hp 18781
其中线程18783和18784各自的CPU都达到了99%。
jstack 18781 >> jstack.out
把JVM的线程信息导出到文件。

printf '%xn' 18783
printf '%xn' 18784
线程ID转换成16进制

在导出的线程栈文件jstack.out里查找495f和4960，对应的是gc线程，初步推断是内存泄漏导致的频繁gc。

jstat -gcutil 18781 1s

可以看到每隔几秒就会full gc，而且Eden和Old都是99%，就是说每次full gc都没有回收到多少内存，所以一直在反复的跑。

现在要把虚拟机内存导出，分析内存中是哪些对象占用大量空间不释放，因为HeapDump在生产环境是没有打开的（幸好没有打开HeapDumpBeforeFullGC ，不然就不止是CPU高了，按这几秒full gc一次的频率，用不了多久把磁盘也要撑爆），所以要用到一个小工具jinfo。

jinfo是jdk中自带的一个工具，用来查看运行中的虚拟机的参数，甚至在运行时动态修改一些JVM参数。
java -XX:+PrintFlagsFinal -version | grep manageable

选项-XX:+PrintFlagsFinal可以列出所有的JVM flag，而其中的标注为manageable 的flag则是可通过JDK management interface（-XX:+PrintFlagsFinal）动态修改。

用jinfo打开以下选项，把full gc前后的虚拟机内存dump下来。
jinfo -flag +PrintGC 18781
jinfo -flag +PrintGCDetails 18781
jinfo -flag HeapDumpPath=/home/work/data/heapdump 18781
jinfo -flag +HeapDumpBeforeFullGC 18781
jinfo -flag +HeapDumpAfterFullGC 18781

PrintGC和PrintGCDetails把gc日志输出到了nohup.out，查看nohup文件，可以看到full gc前后各dump了一次虚拟机内存，然后赶紧用jinfo关掉gc选项，选项前+号表示打开，-号表示关闭。

jinfo -flag -HeapDumpBeforeFullGC 18781
jinfo -flag -HeapDumpAfterFullGC 18781

在HeapDumpPath下找到dump下来的hprof文件，用mat打开，Linux下没有找到相关的工具，所以我先把文件下载到本机，用window版的mat打开。

SessionFactoryImpl占了1个多G，超过99%。打开Reports>Leak Suspects

Retained Size=当前对象大小+当前对象可直接或间接引用到的对象的大小总和，所以问题出在第一项的引用链上。点这一项的List Objects>with incoming references.

这个queryPlanCache是hibernate对SQL语句的缓存，可以参考stackoverflow上一位前辈的经验，https://stackoverflow.com/que...，看来是太多数据库in查询造成了大量的SQL缓存，此时回头再看线程栈stack.out的信息，确实有很多Running状态的at com.sun.proxy.$Proxy131.findByIdIn(Unknown Source)，这样就说的通了。

下一步，优化代码吧。