问题呈现:现网CPU飙高,Full GC告警
CGI 处事宣布到现网后,现网呆板呈现了Full GC告警,同时CPU飙高99%。在优先规复现网处事正常后,开始着手定位Full GC的问题。在现场只可以或许抓到四个GC线程占用了很高的CPU,无法抓到激发Full GC的线程。查察了办变乱障期间的错误日志,发明更多的是由于Full GC引起的问题处事异常日志,无法确定Full GC的来源。为了查找问题的来源,只能从宣布自己入手去盘查题,发明一次bugfix的提交,有大概触发一个死轮回逻辑:
for(int i = 1 ;i <= totalPage ;i++) { String path = path_prefix + "?cmd=txt_preview&page=" + String.valueOf(i) + "&sign=" + fileSignature; url_list.add(path); }
轮回中的参数 totalPage
为 long 范例,由一个外部参数举办赋值。当外部参数很是大,高出 int 的最大值时,i
递增到int的最大值后,i++
会产生翻转,酿成一个负数,从而使 for 会进入死轮回。操作下面这段代码可以试验:
public static void main(String[] args) { long totalPage = Long.MAX_VALUE; for(int i = 0 ;i<totalPage;i++){ if(i<0){ System.out.println(i); } } }
通过日志,发明外部确实通报了一个很是大的参数:
苏州软件公司 建须要信息的日志" class="aligncenter size-full wp-image-29892" title="610439-20180914171537456-2117831862" src="/uploads/allimg/c180920/153IX21501B0-1X64.png" />
确认了当掷中逻辑的时候,会进入一个死轮回。在轮回中不绝举办字符串的拼接与list的Add操纵,很快就会耗尽JVM堆内存导致Full GC。颠末测算,昆山软件公司,实际上并不需要死轮回,只要是一个较量大的轮回,就可以或许激发Full GC。对totlePage
的巨细做了限定后,宣布了新版本,没有再呈现Full GC的问题。
现场还原:重现问题,摸索定位思路
回首排盘查题的进程并不高效,最开始猜疑过是否是打包有问题或利用的jdk版本差池,花了较多的时间确认打包问题。另一方面,宣布带出的代码较多,通过反复review代码无法很快锁定问题。为了摸索一种更有效的问题定位要领,我将有问题的代码从头陈设到呆板上,手动结构请求触发bug,摸索定位此类问题的通用思路。
1) 在 Java 处事上开启 JMX,在当地利用 VisualVm 来查察 Java 处事在运行进程中的内存、GC、线程等信息。VisualVM 是 Sun 的一个 OpenJDK 项目,它是集成了多个 JDK 呼吁东西的一个可视化东西,它主要用来监控 JVM 的运行环境,可以用它来查察和欣赏 Heap Dump、Thread Dump、内存工具实例环境、GC 执行环境、CPU 耗损以及类的装载环境,也可以利用它来建设须要信息的日志。
苏州软件公司 建须要信息的日志" class="aligncenter size-large wp-image-29893" title="610439-20180914171601606-395373695" src="/uploads/allimg/c180920/153IX21503420-21033.png" />
可以看到逻辑被掷中的时候,CPU确实是升到100%的,此时也产生了Full GC告警。实验着多发了屡次请求,处事直接就挂掉了。这里有个问题是:不是已经Full GC了吗,为什么还会产生OOM?实际上,固然JVM已经开始接纳内存,可是由于工具被引用,这些内存是接纳不掉的。从GC日志可以看到接纳的环境:
苏州软件公司 建须要信息的日志" class="aligncenter size-large wp-image-29894" title="610439-20180914171611464-1898061671" src="/uploads/allimg/c180920/153IX21510450-350I.png" />
从GC日志中可以看到,新生代的Eden区域与暮年月都已经被占满。假如新生代放不下工具的时候,object会直接被放到暮年月中。除了GC日志,也可以利用jstat呼吁来堆Java堆内存的利用环境举办统计展示:
jstat -gcutil 12309 1000 10
1000为统计的隔断,单元为毫秒,10为统计的次数,输出如下:
苏州软件公司 建须要信息的日志" class="aligncenter size-full wp-image-29895" title="610439-20180914171644184-360950821" src="/uploads/allimg/c180920/153IX21513Z-41622.png" />
从输出中同样可以看到E(Eden)区与O(Old)区都已经被占满了。其他几个输出项的寄义如下:
可以看到JVM一直在实验接纳暮年月,可是一直没能将内存接纳返来。
2)可以登上呆板,确认下是什么线程使 CPU 飙高。先ps查察 Java 历程的 PID:
苏州软件公司 建须要信息的日志" class="aligncenter size-full wp-image-29896" title="610439-20180914171735005-189532605" src="/uploads/allimg/c180920/153IX2151aF-5SR.png" />
拿到历程 pid 后,可以利用 top 呼吁,来看是什么线程占用了 CPU。
top -p 12309 -H
-p
用于指定历程,-H
用于获取每个线程的信息,从 top 输出的内容,可以看到有四个线程占用了很是高的 CPU:
苏州软件公司 建须要信息的日志" class="aligncenter size-full wp-image-29897" title="610439-20180914171748829-1934986704" src="/uploads/allimg/c180920/153IX21521420-64L3.png" />