GC問題
線上常出現(xiàn)的GC問題一般分為以下三種：
- GC 時(shí)間過長(zhǎng)返弹。這種會(huì)影響用戶的體驗(yàn)锈玉，這個(gè)時(shí)候就需要觀察日志，調(diào)整某些 JVM 參數(shù)义起。
- 發(fā)生了OOM拉背。這種情況就比較嚴(yán)重了，服務(wù)阻塞默终，我們要尋找背后的原因椅棺。
- 占用大量系統(tǒng)資源（主要探討堆外內(nèi)存溢出），服務(wù)進(jìn)程被killer齐蔽。這種情況就更嚴(yán)重了两疚，服務(wù)直接被動(dòng)停機(jī)，連異常日志都不留下含滴。
下手解決思路
想要下手解決 GC 問題诱渤，我們以三個(gè)篇章來逐步討論。
- 壓測(cè)觀察并調(diào)試GC-JVisualVM
- 線上OOM異常處理-dump堆信息+MAT
- 程序被動(dòng)停機(jī)（堆外內(nèi)存排查）
上線前壓測(cè)并觀察調(diào)試GC情況
我們可以想到的優(yōu)化手段蛙吏，包括代碼優(yōu)化源哩、擴(kuò)容、參數(shù)優(yōu)化鸦做，甚至我們的估算励烦，都需要一些支撐信息加以判斷。這時(shí)候就需要一些信息收集手段泼诱。
JVisualVM 工具使用
JDK自帶JVM監(jiān)控工具坛掠，可以實(shí)時(shí)觀察JVM進(jìn)程相關(guān)情況。但因?yàn)檫h(yuǎn)程連接JVM進(jìn)程的話治筒，需要遠(yuǎn)程進(jìn)程啟動(dòng)JMX服務(wù)屉栓，故不適合線上環(huán)境JVM觀察，比較適合測(cè)試環(huán)境搭配壓測(cè)調(diào)試使用耸袜。
JDK6之后就在JDK中自帶了友多，工具啟動(dòng)路徑 jdk*/bin/jvisualvm.exe
一般還需安裝一個(gè)插件Visual GC（官網(wǎng)下載 http://visualvm.github.io/ ---> Plugins）
visual gc 指數(shù)圖示
命令行指令
當(dāng)然直接使用JDK命令行指令也可做到JVM實(shí)時(shí)觀察。
- jps：查看正在運(yùn)行JVM相關(guān)進(jìn)程信息
- jstat：查看指定JVM的運(yùn)行狀態(tài)信息（類加載堤框，內(nèi)存域滥，垃圾回收纵柿，即時(shí)編譯）
- jinfo：查看/調(diào)整指定JVM的各項(xiàng)參數(shù)
- jmap：生成指定JVM堆轉(zhuǎn)儲(chǔ)快照（dump），及查詢堆與方法區(qū)的信息
- jstack：生成指定JVM棧（線程）快照
// TODO 后續(xù)補(bǔ)充
GC 日志輸出
你可能感受到启绰，最近幾年 Java 的版本更新速度是很快的昂儒，JVM 的參數(shù)配置其實(shí)變化也很大。就拿 GC 日志這一塊來說委可，Java 9 幾乎是推翻重來渊跋。網(wǎng)絡(luò)上的一些文章，把這些參數(shù)寫的亂七八糟着倾，根本不能投入生產(chǎn)拾酝。如果你碰到不能被識(shí)別的參數(shù)，先確認(rèn)一下自己的 Java 版本屈呕。
在事故出現(xiàn)的時(shí)候微宝，通常并不是那么溫柔。你可能在半夜里就能接到報(bào)警電話虎眨，這是因?yàn)楹芏喽〞r(shí)任務(wù)都設(shè)定在夜深人靜的時(shí)候執(zhí)行蟋软。
這個(gè)時(shí)候，再去看 jstat 已經(jīng)來不及了嗽桩，我們需要保留現(xiàn)場(chǎng)岳守。這個(gè)便是看門狗的工作，看門狗可以通過設(shè)置一些 JVM 參數(shù)進(jìn)行配置碌冶。
那在實(shí)踐中湿痢，要怎么用呢？請(qǐng)看下面命令行扑庞。
Java 8
我們先看一下 JDK8 中的使用譬重。
#!/bin/sh
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDetails"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCDateStamps"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintGCApplicationStoppedTime"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -XX:+PrintTenuringDistribution"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xloggc:${LOG_DIR}/gc_%p.log"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
合成一行。
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps
-XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution
-Xloggc:/tmp/logs/gc_%p.log -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log
-XX:-OmitStackTraceInFastThrow
然后我們來解釋一下這些參數(shù)：
| 參數(shù) | 意義 |
|---|---|
| -verbose:gc | 打印 GC 日志 |
| PrintGCDetails | 打印詳細(xì) GC 日志 |
| PrintGCDateStamps | 系統(tǒng)時(shí)間罐氨，更加可讀臀规，PrintGCTimeStamps 是 JVM 啟動(dòng)時(shí)間 |
| PrintGCApplicationStoppedTime | 打印 STW 時(shí)間 |
| PrintTenuringDistribution | 打印對(duì)象年齡分布，對(duì)調(diào)優(yōu) MaxTenuringThreshold 參數(shù)幫助很大 |
| loggc | 將以上 GC 內(nèi)容輸出到文件中 |
OOM相關(guān)參數(shù)：
| 參數(shù) | 意義 |
|---|---|
| HeapDumpOnOutOfMemoryError | OOM 時(shí) Dump 信息栅隐，非常有用 |
| HeapDumpPath | Dump 文件保存路徑 |
| ErrorFile | 錯(cuò)誤日志存放路徑 |
注意到我們還設(shè)置了一個(gè)參數(shù) OmitStackTraceInFastThrow塔嬉，這是 JVM 用來縮簡(jiǎn)日志輸出的。
開啟這個(gè)參數(shù)之后租悄，如果你多次發(fā)生了空指針異常谨究，將會(huì)打印以下信息。
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
在實(shí)際生產(chǎn)中泣棋，這個(gè)參數(shù)是默認(rèn)開啟的胶哲，這樣就導(dǎo)致有時(shí)候排查問題非常不方便（很多研發(fā)對(duì)此無能為力），我們這里把它關(guān)閉潭辈，但這樣它會(huì)輸出所有的異常堆棧鸯屿，日志會(huì)多很多俩檬。
Java 13
再看下 JDK 13 中的使用。
從 Java 9 開始碾盟，移除了 40 多個(gè) GC 日志相關(guān)的參數(shù)。具體參見 JEP 158技竟。所以這部分的日志配置有很大的變化冰肴。
我們同樣看一下它的生成腳本。
#!/bin/sh
LOG_DIR="/tmp/logs"
JAVA_OPT_LOG=" -verbose:gc"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file=${LOG_DIR}/gc_%p.log:tags,uptime,time,level"
JAVA_OPT_LOG="${JAVA_OPT_LOG} -Xlog:safepoint:file=${LOG_DIR}/safepoint_%p.log:tags,uptime,time,level"
JAVA_OPT_OOM=" -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=${LOG_DIR} -XX:ErrorFile=${LOG_DIR}/hs_error_pid%p.log "
JAVA_OPT="${JAVA_OPT_LOG} ${JAVA_OPT_OOM}"
JAVA_OPT="${JAVA_OPT} -XX:-OmitStackTraceInFastThrow"
echo $JAVA_OPT
合成一行展示榔组。
-verbose:gc -Xlog:gc,gc+ref=debug,gc+heap=debug,gc+age=trace:file
=/tmp/logs/gc_%p.log:tags,uptime,time,level -Xlog:safepoint:file=/tmp
/logs/safepoint_%p.log:tags,uptime,time,level -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/tmp/logs -XX:ErrorFile=/tmp/logs/hs_error_pid%p.log
-XX:-OmitStackTraceInFastThrow
可以看到 GC 日志的打印方式熙尉，已經(jīng)完全不一樣，但是比以前的日志參數(shù)規(guī)整了許多搓扯。
我們除了輸出 GC 日志检痰，還輸出了 safepoint 的日志。這個(gè)日志對(duì)我們分析問題也很重要锨推，那什么叫 safepoint 呢铅歼？
safepoint 是 JVM 中非常重要的一個(gè)概念，指的是可以安全地暫停線程的點(diǎn)换可。
當(dāng)發(fā)生 GC 時(shí)椎椰，用戶線程必須全部停下來，才可以進(jìn)行垃圾回收沾鳄，這個(gè)狀態(tài)我們可以認(rèn)為 JVM 是安全的（safe）慨飘，整個(gè)堆的狀態(tài)是穩(wěn)定的。
如果在 GC 前译荞，有線程遲遲進(jìn)入不了 safepoint瓤的，那么整個(gè) JVM 都在等待這個(gè)阻塞的線程，會(huì)造成了整體 GC 的時(shí)間變長(zhǎng)吞歼。
所以呢圈膏，并不是只有 GC 會(huì)掛起 JVM，進(jìn)入 safepoint 的過程也會(huì)浆熔。這個(gè)概念本辐，如果你有興趣可以自行深挖一下，一般是不會(huì)出問題的医增。
如果有人問起你在項(xiàng)目中都使用了哪些打印 GC 日志的參數(shù)慎皱，上面這些信息肯定是不很好記憶。你需要進(jìn)行以下總結(jié)叶骨。比如：
“我一般在項(xiàng)目中輸出詳細(xì)的 GC 日志茫多，并加上可讀性強(qiáng)的 GC 日志的時(shí)間戳。特別情況下我還會(huì)追加一些反映對(duì)象晉升情況和堆詳細(xì)信息的日志忽刽，用來排查問題天揖。另外夺欲，OOM 時(shí)自動(dòng) Dump 堆棧，我一般也會(huì)進(jìn)行配置今膊⌒┰模”
GC 日志的意義
我們首先看一段日志，然后簡(jiǎn)要看一下各個(gè)階段的意義斑唬。
- 表示 GC 發(fā)生的時(shí)間市埋，一般使用可讀的方式打印恕刘；
- 表示日志表明是 G1 的“轉(zhuǎn)移暫停: 混合模式”缤谎，停頓了約 223ms；
- 表明由 8 個(gè) Worker 線程并行執(zhí)行褐着，消耗了 214ms坷澡；
- 表示 Diff 越小越好，說明每個(gè)工作線程的速度都很均勻含蓉；
- 表示外部根區(qū)掃描频敛，外部根是堆外區(qū)。JNI 引用馅扣，JVM 系統(tǒng)目錄姻政，Classloaders 等；
- 表示更新 RSet 的時(shí)間信息岂嗓；
- 表示該任務(wù)主要是對(duì) CSet 中存活對(duì)象進(jìn)行轉(zhuǎn)移（復(fù)制）汁展；
- 表示花在 GC 之外的工作線程的時(shí)間；
- 表示并行階段的 GC 總時(shí)間厌殉；
- 表示其他清理活動(dòng)食绿；
- 表示收集結(jié)果統(tǒng)計(jì)；
- 表示時(shí)間花費(fèi)統(tǒng)計(jì)公罕。
