最近发现公司一个主机的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是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 18781jinfo -flag +PrintGCDetails 18781jinfo -flag HeapDumpPath=/home/work/data/heapdump 18781jinfo -flag +HeapDumpBeforeFullGC 18781jinfo -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文件,用打开,Linux下没有找到相关的工具,所以我先把文件下载到本机,用window版的mat打开。
SessionFactoryImpl占了1个多G,超过99%。打开Reports>Leak Suspects
Retained Size=当前对象大小+当前对象可直接或间接引用到的对象的大小总和,所以问题出在第一项的引用链上。点这一项的List Objects>with incoming references.
这个queryPlanCache是hibernate对SQL语句的缓存,可以参考stackoverflow上一位前辈的经验,,看来是太多数据库in查询造成了大量的SQL缓存,此时回头再看线程栈stack.out的信息,确实有很多Running状态的at com.sun.proxy.$Proxy131.findByIdIn(Unknown Source),这样就说的通了。
下一步,优化代码吧。