arthas 排查内存溢出_Java程序线上故障排查
這篇文章是在公司做了不少的線上Java服務(wù)故障排查和優(yōu)化之后的一個總結(jié)，可以作為一個工具清單，在分析問題的時候需要有整體思路：全局觀，先從系統(tǒng)層面入手，大致定位方向(內(nèi)存，cpu，磁盤，網(wǎng)絡(luò))，然后再去分析具體的進(jìn)程。
一、Linux
內(nèi)存和cpu
內(nèi)存和cpu問題是出問題最多的一個點，因為有些命令如top同時可以觀察到內(nèi)存和cpu所以放在一起。
top命令
常用參數(shù)： -H 打印具體的線程， -p 打印某個進(jìn)程 進(jìn)入后 按數(shù)字1 可以切換cpu的圖形看有幾個核
下面是我的測試環(huán)境shell:
top - 14:28:49 up 7 min, 3 users, load average: 0.08, 0.26, 0.19
Tasks: 221 total, 2 running, 219 sleeping, 0 stopped, 0 zombie
%Cpu(s): 5.1 us, 3.4 sy, 0.0 ni, 91.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 985856 total, 81736 free, 646360 used, 257760 buff/cache
KiB Swap: 2094076 total, 1915196 free, 178880 used. 141592 avail Mem
我一般重點關(guān)注的指標(biāo)有：
%Cpu(s): 5.1 us, 3.4 sy, 0.0 wa
這里可以非常直觀的看到當(dāng)前cpu的負(fù)載情況，us用戶cpu占用時間，sy是系統(tǒng)調(diào)用cpu占用時間，wa是cpu等待io的時間，前面兩個比較直觀，但是第三個其實也很重要，如果wa很高，那么你就該重點關(guān)注下磁盤的負(fù)載了，尤其是像mysql這種服務(wù)器。
load average: 0.08, 0.26, 0.19
cpu任務(wù)隊列的負(fù)載，這個隊列包括正在運(yùn)行的任務(wù)和等待運(yùn)行的任務(wù)，三個數(shù)字分別是1分鐘、5分鐘和15分鐘的平均值。這個和cpu占用率一般是正相關(guān)的，反應(yīng)的是用戶代碼，如果超過了內(nèi)核數(shù)，表示系統(tǒng)已經(jīng)過載。也就是說如果你是8核，那么這個數(shù)字小于等于8的負(fù)載都是沒問題的，我看網(wǎng)上的建議一般這個值不要超過ncpu*2-2為好。
KiB Mem : 985856 total, 81736 free, 646360 used, 257760 buff/cache
內(nèi)存占用情況，total總內(nèi)存，free空余內(nèi)存， used已經(jīng)分配內(nèi)存，buff/cache塊設(shè)備和緩沖區(qū)占用的內(nèi)存，因為Linux的內(nèi)存分配，如果有剩余內(nèi)存，他就會將內(nèi)存用于cache，這樣可以較少磁盤的讀寫提高效率，如果有應(yīng)用申請內(nèi)存，buff/cache這部分內(nèi)存也是可用的，所以正真的剩余內(nèi)存應(yīng)該是free+buff/cache
swap
線上服務(wù)器一般都是禁用狀態(tài)，所以不用看這項。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
這一欄主要是看進(jìn)程的詳情，重點是%CPU %MEM，上面看的是整個服務(wù)器的負(fù)載，這里是每個進(jìn)程的負(fù)載。還有看看S這個指標(biāo)，這個代碼了進(jìn)程的狀態(tài)，有時候有些進(jìn)程會出現(xiàn)T(暫停)這個狀態(tài)。
網(wǎng)絡(luò)
ss
netstat的高性能版，參數(shù)都基本一致
常用參數(shù)： -n 打印數(shù)字端口號 -t tcp連接 -l 監(jiān)聽端口 -a 所有端口 -p 進(jìn)程號 -s 打印統(tǒng)計信息
ss -s示例：
Total: 1732 (kernel 1987)
TCP: 42373 (estab 1430, closed 40910, orphaned 2, synrecv 0, timewait 40906/0), ports 1924
Transport Total IP IPv6
* 1987 - -
RAW 18 9 9
UDP 18 11 7
TCP 1463 503 960
可以看到整體的連接情況，如timewait過高，連接數(shù)過高等情況
然后使用ss -ntap|grep 進(jìn)程號 or 端口號查看進(jìn)程的連接
ping
查看時延和丟包情況
mtr
查看丟包請求
磁盤
磁盤問題在mysql服務(wù)器中非常常見，很多時候mysql服務(wù)器的CPU不高但是卻出現(xiàn)慢查詢?nèi)罩撅j升，就是因為磁盤出現(xiàn)了瓶頸。還有mysql的備份策略，如果沒有監(jiān)控磁盤空間，可能出現(xiàn)磁盤滿了服務(wù)不可用的現(xiàn)象。
**iostat命令 **
常用參數(shù)： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個幾秒刷新 顯示次數(shù)
這個是我查看磁盤負(fù)載的主要工具，也可以顯示cpu的負(fù)載，不過我一般用iostat -kdx 2 10,下面是我測試環(huán)境執(zhí)行情況：
root@ubuntu:~# iostat -kdx 2 10
Linux 4.13.0-38-generic (ubuntu) 11/18/2018 _x86_64_(1 CPU)
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 24.75 196.05 121.66 9.75 2481.33 961.29 52.40 0.44 3.33 1.12 30.95 0.51 6.71
scd0 0.00 0.00 0.02 0.00 0.08 0.00 7.00 0.00 0.25 0.25 0.00 0.25 0.00
我一般重點關(guān)注的指標(biāo)有：
rkB/s和wkB/s: 分別對應(yīng)讀寫速度
avgqu-sz: 讀寫隊列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時間(毫秒)，分別是讀寫，讀和寫三個平均值。這個時間都包括在隊列中等待的時間和實際處理讀寫請求的時間，還有svctm這個參數(shù)，他說的是實際處理讀寫請求的時間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經(jīng)廢棄，所以一般我看的是這三個。
%util: 這個參數(shù)直觀的看磁盤的負(fù)載情況，我首先看的就是這個參數(shù)。和top的wa命令有關(guān)聯(lián)。
df
查看文件系統(tǒng)的容量
常用參數(shù)： -h 友好的單位 如Kb，Mb等
du
統(tǒng)計具體的文件大小
常用參數(shù)： -h 友好的單位 如Kb，Mb等 -s 總計，而不是進(jìn)入每個子目錄分別統(tǒng)計
場景：例如系統(tǒng)磁盤空間不足時，先通過df命令定位到具體的掛載目錄，在進(jìn)去掛載目錄后，使用
du -sh *查看各個文件或者子目錄的大小定位具體文件
這里還有l(wèi)s命令，可以通過加-h和-S(按大小排序)
iostat命令
常用參數(shù)： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個幾秒刷新 顯示次數(shù)
這個是我查看磁盤負(fù)載的主要工具，也可以顯示cpu的負(fù)載，不過我一般用iostat -kdx 2 10,下面是我測試環(huán)境執(zhí)行情況：
root@ubuntu:~# iostat -kdx 2 10
Linux 4.13.0-38-generic (ubuntu) 11/18/2018 _x86_64_(1 CPU)
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 24.75 196.05 121.66 9.75 2481.33 961.29 52.40 0.44 3.33 1.12 30.95 0.51 6.71
scd0 0.00 0.00 0.02 0.00 0.08 0.00 7.00 0.00 0.25 0.25 0.00 0.25 0.00
我一般重點關(guān)注的指標(biāo)有：
rkB/s和wkB/s: 分別對應(yīng)讀寫速度
avgqu-sz: 讀寫隊列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時間(毫秒)，分別是讀寫，讀和寫三個平均值。這個時間都包括在隊列中等待的時間和實際處理讀寫請求的時間，還有svctm這個參數(shù)，他說的是實際處理讀寫請求的時間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經(jīng)廢棄，所以一般我看的是這三個。
%util: 這個參數(shù)直觀的看磁盤的負(fù)載情況，我首先看的就是這個參數(shù)。和top的wa命令有關(guān)聯(lián)。
lsof
列出當(dāng)前系統(tǒng)打開文件，因為在linux下一切皆是文件，連接，硬件等均被描述為文件，所以這個命令也十分有用。
常用參數(shù)：
-p 查看某個進(jìn)程的文件
直接加文件名 查看哪些進(jìn)程打開了文件
+d 目錄 查看哪些進(jìn)程打開了目錄以及下面的文件(不遞歸，+D是遞歸)
Sar
最后補(bǔ)充一個sar(System Activity Reporter)命令，如果系統(tǒng)沒有一個良好的監(jiān)控，那么這個命令對于排查問題是很好的補(bǔ)充，很多時候去排查問題的時候發(fā)現(xiàn)問題已經(jīng)沒了，可以通過這個命令查看系統(tǒng)的活動情況，比如各個時間段cpu情況，內(nèi)存情況。
常用參數(shù)：
-r 內(nèi)存信息
-q loader信息，運(yùn)行隊列情況
-u cpu信息
-W Swap換頁情況
/proc文件系統(tǒng)
/proc是個虛擬文件系統(tǒng)，是內(nèi)核的一些數(shù)據(jù)，很多l(xiāng)inux命令的都是通過解析/proc文件系統(tǒng)實現(xiàn)的，每個進(jìn)程都會有一個以pid為目錄名的子目錄存在，通過解析/proc下的進(jìn)程目錄可以得到很多進(jìn)程的設(shè)置信息和資源占用信息等。
這里簡單說個排查過的問題，當(dāng)時我們線上有個服務(wù)，正常ssh登錄的情況下,我們設(shè)置了ulimit中的open files為(進(jìn)程可打開的最大描述符數(shù)量)100000，但是有一次在服務(wù)的日志中發(fā)現(xiàn)有報錯說文件描述符不夠用。所以
二、JVM
java -XX:+PrintFlagsInitial 可以查看所以的jvm默認(rèn)參數(shù)，其中帶有manageable表示運(yùn)行時可以動態(tài)修改。
20:45 [root@centos]$ java -XX:+PrintFlagsInitial |grep manageable
intx CMSAbortablePrecleanWaitMillis = 100 {manageable}
intx CMSTriggerInterval = -1 {manageable}
intx CMSWaitDuration = 2000 {manageable}
bool HeapDumpAfterFullGC = false {manageable}
bool HeapDumpBeforeFullGC = false {manageable}
bool HeapDumpOnOutOfMemoryError = false {manageable}
ccstr HeapDumpPath = {manageable}
uintx MaxHeapFreeRatio = 70 {manageable}
uintx MinHeapFreeRatio = 40 {manageable}
bool PrintClassHistogram = false {manageable}
bool PrintClassHistogramAfterFullGC = false {manageable}
bool PrintClassHistogramBeforeFullGC = false {manageable}
bool PrintConcurrentLocks = false {manageable}
bool PrintGC = false {manageable}
bool PrintGCDateStamps = false {manageable}
bool PrintGCDetails = false {manageable}
bool PrintGCID = false {manageable}
bool PrintGCTimeStamps = false {manageable}
Java堆和垃圾收集器
java內(nèi)存結(jié)構(gòu)
堆內(nèi)存結(jié)構(gòu)：
java8元空間改動：
java 7種垃圾收集器：
常見搭配：
java8默認(rèn)：Parallel Scavenge和 Parallel Old
低延遲：ParNew和CMS
java8以后可以直接使用G1，參數(shù)比較簡單
ParNew
Serial的并行版本
Parallel Scavenge
注重的是吞吐量，吞吐量=運(yùn)行用戶代碼時間/(運(yùn)行用戶代碼時間+垃圾收集時間)，其具有自適應(yīng)的特性
控制最大垃圾收集停頓時間的-XX:MaxGCPauseMillis參數(shù)
MaxGCPauseMillis參數(shù)允許的值是一個大于0的毫秒數(shù)，收集器將盡力保證內(nèi)存回收花費(fèi)的時間不超過設(shè)定值。不過大家不要異想天開地認(rèn)為如果把這個參數(shù)的值設(shè)置得稍小一點就能使得系統(tǒng)的垃圾收集速度變得更快，GC停頓時間縮短是以犧牲吞吐量和新生代空間來換取的：系統(tǒng)把新生代調(diào)小一些，收集300MB新生代肯定比收集500MB快吧，這也直接導(dǎo)致垃圾收集發(fā)生得更頻繁一些，原來10秒收集一次、每次停頓100毫秒，現(xiàn)在變成5秒收集一次、每次停頓70毫秒。停頓時間的確在下降，但吞吐量也降下來了。
直接設(shè)置吞吐量大小的 -XX:GCTimeRatio參數(shù)
GCTimeRatio參數(shù)的值應(yīng)當(dāng)是一個大于0小于100的整數(shù)，也就是垃圾收集時間占總時間的比率。如果把此參數(shù)設(shè)置為19，那允許的最大GC時間就占總時間的5%(即1 /(1+19))，默認(rèn)值為99，就是允許最大1%(即1 /(1+99))的垃圾收集時間。
UseAdaptiveSizePolicy開關(guān)參數(shù)
-XX:+UseAdaptiveSizePolicy是一個開關(guān)參數(shù)，當(dāng)這個參數(shù)打開之后，就不需要手工指定新生代的大小(-Xmn)、Eden與Survivor區(qū)的比例(-XX:SurvivorRatio)、晉升老年代對象年齡(-XX:PretenureSizeThreshold)等細(xì)節(jié)參數(shù)了，虛擬機(jī)會根據(jù)當(dāng)前系統(tǒng)的運(yùn)行情況收集性能監(jiān)控信息，動態(tài)調(diào)整這些參數(shù)以提供最合適的停頓時間或最大的吞吐量，這種調(diào)節(jié)方式稱為GC自適應(yīng)的調(diào)節(jié)策略(GC Ergonomics)。
說說UseAdaptiveSizePolicy參數(shù)，加了這個參數(shù)-XX:SurvivorRatio會失效，所以有些人會發(fā)現(xiàn)新生代比例未如自己的預(yù)期，而UseAdaptiveSizePolicy有默認(rèn)是開啟的
CMS
并發(fā)垃圾收集器，注重的是時延，有分配擔(dān)保失敗的風(fēng)險
CMS收集器的GC周期由6個階段組成。其中4個階段(名字以Concurrent開始的)與實際的應(yīng)用程序是并發(fā)執(zhí)行的，而其他2個階段需要暫停應(yīng)用程序線程。
初始標(biāo)記：為了收集應(yīng)用程序的對象引用需要暫停應(yīng)用程序線程，該階段完成后，應(yīng)用程序線程再次啟動。
并發(fā)標(biāo)記：從第一階段收集到的對象引用開始，遍歷所有其他的對象引用。
并發(fā)預(yù)清理：改變當(dāng)運(yùn)行第二階段時，由應(yīng)用程序線程產(chǎn)生的對象引用，以更新第二階段的結(jié)果。
重標(biāo)記：由于第三階段是并發(fā)的，對象引用可能會發(fā)生進(jìn)一步改變。因此，應(yīng)用程序線程會再一次被暫停以更新這些變化，并且在進(jìn)行實際的清理之前確保一個正確的對象引用視圖。這一階段十分重要，因為必須避免收集到仍被引用的對象。
并發(fā)清理：所有不再被應(yīng)用的對象將從堆里清除掉。
并發(fā)重置：收集器做一些收尾的工作，以便下一次GC周期能有一個干凈的狀態(tài)。
-XX:CMSInitiatingOccupancyFraction=90 (jdk1.5默認(rèn)值68，1.6開始默認(rèn)值92，指設(shè)定CMS在對內(nèi)存占用率達(dá)到70%的時候開始GC(因為CMS會有浮動垃圾,所以一般都較早啟動GC)
-XX:+UseCMSInitiatingOccupancyOnly 只是用設(shè)定的回收閾值(上面指定的70%),如果不指定,JVM僅在第一次使用設(shè)定值,后續(xù)則自動調(diào)整
-XX:+CMSScavengeBeforeRemark 在CMS GC前啟動一次ygc，目的在于減少old gen對ygc gen的引用，降低remark時的開銷
-XX:+CMSParallelRemarkEnabled 并發(fā)標(biāo)記
-XX:+ExplicitGCInvokesConcurrent命令JVM無論什么時候調(diào)用系統(tǒng)GC(system.gc())，都執(zhí)行CMS GC，而不是Full GC
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保證當(dāng)有系統(tǒng)GC調(diào)用時，永久代也被包括進(jìn)CMS垃圾回收的范圍內(nèi)
-XX：UseParNewGC 使用CMS時自動開啟，因為CMS不能和Parallel Scavenge搭配使用
上面的參數(shù)都建議開啟，CMS需要注意的一個問題就是CMSInitiatingOccupancyFraction參數(shù)，這個參數(shù)直接影響CMS回收老年代的時機(jī)，需要結(jié)合自己的業(yè)務(wù)場景來調(diào)整，一般情況下應(yīng)該盡量設(shè)置大一點，但是有一個嚴(yán)重的問題，就是浮動垃圾的問題，如果CMS在并發(fā)收集的時候出現(xiàn)老年代不能存放晉升對象將直接進(jìn)行Full GC使用Serial Old垃圾收集器,所以不能一味追求最大化，如果老年代增長比較慢，那么可以設(shè)置的稍微較大些，如果增長比較快，可以從增大新生代，調(diào)低CMSInitiatingOccupancyFraction入手
最后在提下-XX:+DisableExplicitGC ：禁用顯示gc (system.gc())這個參數(shù)，很多人因為system.gc()會導(dǎo)致Full gc而禁用顯示調(diào)用gc，但是這個參數(shù)最好不要禁用，現(xiàn)在很多服務(wù)端程序都使用了Nio，jvm為了減少內(nèi)存拷貝，采用了直接內(nèi)存，直接內(nèi)存屬于堆外內(nèi)存，java大多使用了Netty這個框架，他幫我們處理堆外內(nèi)存的回收，實現(xiàn)的機(jī)制就是通過調(diào)用system.gc()，發(fā)起Full Gc，Full Gc會回收堆外內(nèi)存，如果將system.gc()禁用，則得等到Full Gc發(fā)生才能回收堆外內(nèi)存，很有可能出現(xiàn)堆外內(nèi)存占用過高影響系統(tǒng)性能或者因為內(nèi)存不足被系統(tǒng)Kill的問題。
gc日志參數(shù)
-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細(xì)日志
-XX:+PrintGCTimeStamps 輸出GC的時間戳(以基準(zhǔn)時間的形式)
-XX:+PrintGCDateStamps 輸出GC的時間戳(以日期的形式，如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在進(jìn)行GC的前后打印出堆的信息
-XX:+PrintGCApplicationStoppedTime // 輸出GC造成應(yīng)用暫停的時間
-Xloggc:../logs/gc.log 日志文件的輸出路徑
-XX:+PrintTenuringDistribution 打印新生代的年齡分布(這里需要注意，如果使用的是Parallel Scavenge，那么打印的時候是沒有年齡分布信息的)
-XX:+UseGCLogFileRotation 開啟日志輪換
-XX:NumberOfGCLogFiles=5 日志保留數(shù)量
-XX:GCLogFileSize=10m 每份日志保留大小
堆參數(shù)
-Xms 最小堆大小
-Xmx 最大堆大小
-Xmn 新生代大小
-XX:SurvivorRatio 新生代中Eden區(qū)與Survivor區(qū)的比例，默認(rèn)值為8
gc日志分析
ParNew Gc日志：
{Heap before GC invocations=4196 (full 3):
par new generation total 1887488K, used 1683093K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000)
eden space 1677824K, 100% used [0x0000000640000000, 0x00000006a6680000, 0x00000006a6680000)
from space 209664K, 2% used [0x00000006a6680000, 0x00000006a6ba5430, 0x00000006b3340000)
to space 209664K, 0% used [0x00000006b3340000, 0x00000006b3340000, 0x00000006c0000000)
concurrent mark-sweep generation total 4194304K, used 1565111K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 59881K, capacity 64953K, committed 66588K, reserved 1107968K
class space used 6615K, capacity 7729K, committed 8224K, reserved 1048576K
2019-10-29T23:48:00.181+0800: 27966.548: [GC (Allocation Failure) 2019-10-29T23:48:00.181+0800: 27966.548: [ParNew
Desired survivor size 107347968 bytes, new threshold 15 (max 15)
- age 1: 2287832 bytes, 2287832 total
- age 2: 132752 bytes, 2420584 total
- age 3: 102408 bytes, 2522992 total
- age 4: 125768 bytes, 2648760 total
- age 5: 145464 bytes, 2794224 total
- age 6: 82808 bytes, 2877032 total
- age 7: 104736 bytes, 2981768 total
- age 8: 79216 bytes, 3060984 total
- age 9: 89496 bytes, 3150480 total
- age 10: 81864 bytes, 3232344 total
- age 11: 91304 bytes, 3323648 total
- age 12: 78912 bytes, 3402560 total
- age 13: 80960 bytes, 3483520 total
- age 14: 91560 bytes, 3575080 total
- age 15: 78992 bytes, 3654072 total
: 1683093K->5343K(1887488K), 0.0342117 secs] 3248204K->1570530K(6081792K), 0.0343754 secs] [Times: user=0.17 sys=0.01, real=0.03 secs]
Heap after GC invocations=4197 (full 3):
par new generation total 1887488K, used 5343K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000)
eden space 1677824K, 0% used [0x0000000640000000, 0x0000000640000000, 0x00000006a6680000)
from space 209664K, 2% used [0x00000006b3340000, 0x00000006b3877f50, 0x00000006c0000000)
to space 209664K, 0% used [0x00000006a6680000, 0x00000006a6680000, 0x00000006b3340000)
concurrent mark-sweep generation total 4194304K, used 1565186K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 59881K, capacity 64953K, committed 66588K, reserved 1107968K
class space used 6615K, capacity 7729K, committed 8224K, reserved 1048576K
}
gc日志中打印了新生代，老年代和元空間等內(nèi)存信息，其中Times: user=0.02 sys=0.01, real=0.01 secs三個時間分別是用戶態(tài)的時間，內(nèi)核態(tài)的時間和墻鐘時間。墻鐘時間表示真正過去的時間，而用戶態(tài)和內(nèi)核態(tài)的時間則是乘了相應(yīng)的cpu核心數(shù)。
CMS GC日志：
2019-10-29T18:03:19.578+0800: 7285.945: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3182477K(4194304K)] 3254261K(6081792K), 0.0044508 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
2019-10-29T18:03:19.582+0800: 7285.949: [CMS-concurrent-mark-start]
2019-10-29T18:03:20.812+0800: 7287.179: [CMS-concurrent-mark: 1.229/1.229 secs] [Times: user=3.86 sys=0.46, real=1.23 secs]
2019-10-29T18:03:20.812+0800: 7287.179: [CMS-concurrent-preclean-start]
2019-10-29T18:03:20.823+0800: 7287.190: [CMS-concurrent-preclean: 0.011/0.011 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
2019-10-29T18:03:20.823+0800: 7287.190: [CMS-concurrent-abortable-preclean-start]
{Heap before GC invocations=896 (full 3):
par new generation total 1887488K, used 1747877K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000)
eden space 1677824K, 100% used [0x0000000640000000, 0x00000006a6680000, 0x00000006a6680000)
from space 209664K, 33% used [0x00000006a6680000, 0x00000006aaae9780, 0x00000006b3340000)
to space 209664K, 0% used [0x00000006b3340000, 0x00000006b3340000, 0x00000006c0000000)
concurrent mark-sweep generation total 4194304K, used 3182477K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 60431K, capacity 66281K, committed 66588K, reserved 1107968K
class space used 6828K, capacity 8138K, committed 8224K, reserved 1048576K
2019-10-29T18:03:25.649+0800: 7292.016: [GC (Allocation Failure) 2019-10-29T18:03:25.649+0800: 7292.016: [ParNew
Desired survivor size 107347968 bytes, new threshold 15 (max 15)
- age 1: 1362152 bytes, 1362152 total
- age 3: 124920 bytes, 1487072 total
- age 4: 115256 bytes, 1602328 total
- age 5: 165000 bytes, 1767328 total
- age 6: 99776 bytes, 1867104 total
- age 7: 97728 bytes, 1964832 total
- age 8: 94616 bytes, 2059448 total
- age 9: 93176 bytes, 2152624 total
- age 10: 111352 bytes, 2263976 total
- age 11: 127800 bytes, 2391776 total
- age 12: 85248 bytes, 2477024 total
- age 13: 110984 bytes, 2588008 total
- age 14: 101880 bytes, 2689888 total
- age 15: 96288 bytes, 2786176 total
: 1747877K->18163K(1887488K), 0.0364969 secs] 4930355K->3200776K(6081792K), 0.0366162 secs] [Times: user=0.17 sys=0.00, real=0.04 secs]
Heap after GC invocations=897 (full 3):
par new generation total 1887488K, used 18163K [0x0000000640000000, 0x00000006c0000000, 0x00000006c0000000)
eden space 1677824K, 0% used [0x0000000640000000, 0x0000000640000000, 0x00000006a6680000)
from space 209664K, 8% used [0x00000006b3340000, 0x00000006b44fcd88, 0x00000006c0000000)
to space 209664K, 0% used [0x00000006a6680000, 0x00000006a6680000, 0x00000006b3340000)
concurrent mark-sweep generation total 4194304K, used 3182613K [0x00000006c0000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 60431K, capacity 66281K, committed 66588K, reserved 1107968K
class space used 6828K, capacity 8138K, committed 8224K, reserved 1048576K
}
CMS: abort preclean due to time 2019-10-29T18:03:25.825+0800: 7292.192: [CMS-concurrent-abortable-preclean: 4.952/5.002 secs] [Times: user=10.51 sys=1.44, real=5.01 secs]
2019-10-29T18:03:25.826+0800: 7292.193: [GC (CMS Final Remark) [YG occupancy: 81039 K (1887488 K)]2019-10-29T18:03:25.826+0800: 7292.194: [Rescan (parallel) , 0.0142974 secs]2019-10-29T18:03:25.841+0800: 7292.208: [weak refs processing, 0.0019208 secs]2019-10-29T18:03:25.843+0800: 7292.210: [class unloading, 0.0230836 secs]2019-10-29T18:03:25.866+0800: 7292.233: [scrub symbol table, 0.0054818 secs]2019-10-29T18:03:25.871+0800: 7292.238: [scrub string table, 0.0707817 secs][1 CMS-remark: 3182613K(4194304K)] 3263652K(6081792K), 0.1182958 secs] [Times: user=0.17 sys=0.01, real=0.11 secs]
2019-10-29T18:03:25.946+0800: 7292.313: [CMS-concurrent-sweep-start]
2019-10-29T18:03:27.771+0800: 7294.138: [CMS-concurrent-sweep: 1.825/1.826 secs] [Times: user=3.98 sys=0.52, real=1.82 secs]
2019-10-29T18:03:27.771+0800: 7294.138: [CMS-concurrent-reset-start]
2019-10-29T18:03:27.781+0800: 7294.148: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
JVMTI介紹
JVM相關(guān)參數(shù)：
-agentlib:[=]
加載本機(jī)代理庫 , 例如 -agentlib:jdwp
另請參閱 -agentlib:jdwp=help
-agentpath:[=]
按完整路徑名加載本機(jī)代理庫
-javaagent:[=]
加載 Java 編程語言代理, 請參閱 java.lang.instrument
JVMTI(Java Virtual Machine Tool Interface)即指Java虛擬機(jī)工具接口，它是一套由虛擬機(jī)直接提供的 native 接口，通過這些接口，開發(fā)人員不僅調(diào)試在該虛擬機(jī)上運(yùn)行的 Java 程序，還能查看它們運(yùn)行的狀態(tài)，設(shè)置回調(diào)函數(shù)，控制某些環(huán)境變量(JMX)，從而優(yōu)化程序性能。Java Agent就是基于JVMTI的，所以眾多基于Java Agent的技術(shù)例如APM，遠(yuǎn)程調(diào)試，各種性能剖析同樣是基于這個技術(shù)。
JVMTI 接口：
JNIEXPORT jint JNICALL
Agent_OnLoad(JavaVM *vm, char *options, void *reserved);
JNIEXPORT jint JNICALL
Agent_OnAttach(JavaVM* vm, char* options, void* reserved);
JNIEXPORT void JNICALL
Agent_OnUnload(JavaVM *vm);
-agentpath是c/c++編寫的動態(tài)庫，-agentlib和-javaagent是一個instrument的JVMTIAgent(linux下對應(yīng)的動態(tài)庫是libinstrument.so)。
Attach機(jī)制
Jvm提供一種jvm進(jìn)程間通信的能力，能讓一個進(jìn)程傳命令給另外一個進(jìn)程，并讓它執(zhí)行內(nèi)部的一些操作，比如說我們?yōu)榱俗屃硗庖粋€jvm進(jìn)程把線程dump出來，那么我們跑了一個jstack的進(jìn)程，然后傳了個pid的參數(shù)，告訴它要哪個進(jìn)程進(jìn)行線程dump。
Attach命令列表
static AttachOperationFunctionInfo funcs[] = {
{ "agentProperties", get_agent_properties },
{ "datadump", data_dump },
{ "dumpheap", dump_heap },
{ "load", JvmtiExport::load_agent_library },
{ "properties", get_system_properties },
{ "threaddump", thread_dump },
{ "inspectheap", heap_inspection },
{ "setflag", set_flag },
{ "printflag", print_flag },
{ "jcmd", jcmd },
{ NULL, NULL }
};
Attach流程：
查看java線程：
其中Siginal Dispatcher是處理進(jìn)程信號的線程，Attach Listener正式Attach機(jī)制處理線程。
java自帶工具
jps
查看Java進(jìn)程列表
常用參數(shù)：
-l: 輸出應(yīng)用程序主類完整package名稱或jar完整名稱
-m:輸出主函數(shù)傳入的參數(shù)
jmap
查看JVM堆的情況
常用參數(shù)：
-heap
-dump 這個命令還有兩個常用參數(shù)
live 只dump存活對象，會導(dǎo)致GC
file=file dump文件名
示例：jmap -dump:live,file=heap.dump
這里有兩點，一方面需要注意live會導(dǎo)致GC，有時候在查問題的時候可能不是你預(yù)期的效果，一般查內(nèi)存問題時不加這個選項，另外dump文件如果比較大，可以先壓縮在傳回本地
jstack
查看JVM的堆棧情況，監(jiān)測死鎖等
這個命令比較簡單，一般不用加什么參數(shù)，有時候JVM沒響應(yīng)時可以加-F參數(shù)。一般這個命令可以結(jié)合top，在top定位到占用cpu高的線程后，在具體在Jstack打印的堆棧中查看線程，有時候也需要多次打印堆棧來進(jìn)行對比
jstat
查看JVM gc信息，觀察JVM的GC活動
常用參數(shù)： -gccause 這個參數(shù)包含了-gcutil的信息多了一個gc原因
示例： jstat -gccause 1000
11:19 [supertool@y051]$ jstat -gccause 10711 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
0.00 21.23 95.99 69.88 91.56 82.62 1187 22.511 4 0.141 22.652 Allocation Failure No GC
0.00 21.23 99.51 69.88 91.56 82.62 1187 22.511 4 0.141 22.652 Allocation Failure No GC
21.30 0.00 3.51 69.88 91.56 82.62 1188 22.530 4 0.141 22.671 Allocation Failure No GC
21.30 0.00 7.02 69.88 91.56 82.62 1188 22.530 4 0.141 22.671 Allocation Failure No GC
21.30 0.00 10.14 69.88 91.56 82.62 1188 22.530 4 0.141 22.671 Allocation Failure No GC
21.30 0.00 13.62 69.88 91.56 82.62 1188 22.530 4 0.141 22.671 Allocation Failure No GC
21.30 0.00 16.78 69.88 91.56 82.62 1188 22.530 4 0.141 22.671 Allocation Failure No GC
jinfo
查看設(shè)置的JVM參數(shù)和啟動時的命令行參數(shù)，還可以動態(tài)修改JVM參數(shù)
常用參數(shù)
-flags 查看jvm參數(shù)值
-sysprops 查看系統(tǒng)屬性值
示例：jinfo -flags 10711
Non-default VM flags: -XX:BiasedLockingStartupDelay=0 -XX:CICompilerCount=4 -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=75 -XX:+CMSParallelRemarkEnabled -XX:ErrorFile=null -XX:GCLogFileSize=10485760 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:MaxNewSize=268435456 -XX:MaxTenuringThreshold=15 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=268435456 -XX:NumberOfGCLogFiles=20 -XX:OldPLABSize=16 -XX:OldSize=805306368 -XX:+PrintClassHistogram -XX:+PrintCommandLineFlags -XX:+PrintConcurrentLocks -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:StringTableSize=6000000 -XX:+UseBiasedLocking -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastUnorderedTimeStamps -XX:+UseGCLogFileRotation -XX:+UseParNewGC
Command line: -XX:+UseBiasedLocking -XX:BiasedLockingStartupDelay=0 -XX:+PrintCommandLineFlags -Xms1g -Xmx1g -Xmn256m -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=5006 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Dfile.encoding=UTF-8 -XX:MaxTenuringThreshold=15 -XX:StringTableSize=6000000 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:+PrintClassHistogram -XX:+PrintConcurrentLocks -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=20 -XX:GCLogFileSize=10m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/java/logs -XX:ErrorFile=/var/java/logs/jvm-error.log -Dlog4j.config.file=log4j_.properties -Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory -Dvertx.options.maxEventLoopExecuteTime=100000000 -Dvertx.options.warningExceptionTime=300000000
JDPA(Java Platform Debugger Architecture)
java遠(yuǎn)程調(diào)試，需要jvm啟動時加參數(shù)：-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005
遠(yuǎn)程調(diào)試非常有用，有時候測試環(huán)境很難復(fù)現(xiàn)時，可以用通過遠(yuǎn)程調(diào)試查看線程數(shù)據(jù)
三、三方工具
jprofile
CPU性能分析
抽樣：每隔一段時間，獲取線程棧，分析各個棧上出現(xiàn)的方法的次數(shù)
優(yōu)點：性能高
缺點： 不適合做精確的分析
適用范圍：尋找程序的執(zhí)行熱點，cpu密集型
指令插入：使用增強(qiáng)的技術(shù)修改java class的字節(jié)碼，在函數(shù)的出入口增加埋點
優(yōu)點：數(shù)據(jù)準(zhǔn)確
缺點：導(dǎo)致jvm內(nèi)聯(lián)優(yōu)化失效，性能低
適用范圍：分析具體耗時路徑的各個執(zhí)行時間，io密集型
一般先使用抽樣在定位到大致的范圍，然后使用指令插入分析具體代碼執(zhí)行路徑中的耗時，jprofile可以通過過濾只對指定類進(jìn)行增強(qiáng)
Thread Status：選擇線程統(tǒng)計狀態(tài)，Runnable顯示的是cpu時間，不包含sleep這種時間一般都是這個模式。還可以使用IO Net模式分析io等待，Wait分析鎖競爭模式
Call tree filters ：調(diào)用樹過濾：用于過濾不需要的類，例如你使用web框架，棧中起始的方法都是框架中的代碼，最后才是你的業(yè)務(wù)代碼，這時候可以使用Call tree filters來過濾不需要的類型，減少統(tǒng)計造成的性能開銷
內(nèi)存剖析
分析內(nèi)存泄漏的利器，主要是看內(nèi)存中內(nèi)存占比和大對象。很多時候如果有內(nèi)存泄漏基本都是以為某些類型的對象占用了大頭。
arthas (類似btrace的工具)
Arthas 是Alibaba開源的Java診斷工具。線上debug的工具，很多時候因為性能和安全等原因我們不能直接遠(yuǎn)程調(diào)試線上的jvm，這時候我們可以使用arthas來查看內(nèi)存的數(shù)據(jù)，方法調(diào)用情況，打印日志信息等。
比較常用的：
watch 看方法調(diào)用情況 -c 統(tǒng)計周期，默認(rèn)值為120秒
monitor 統(tǒng)計方法調(diào)用信息
getstatic 查看靜態(tài)變量
logger 查看和修改logger
trace 方法內(nèi)部調(diào)用路徑，并輸出方法路徑上的每個節(jié)點上耗時
示例：
monitor -c 5 com.miaozhen.bazaro.deal.PreferredDealFilterService filter
watch com.miaozhen.bazaro.share.manager.util.DealManager getDspToDealsByPid "returnObj"
gceasy
四、實際案例
連接泄漏
場景描述：我們公司的用戶服務(wù)對接了第三方騰訊云通信服務(wù)，在用戶注冊的時候我們需要走h(yuǎn)ttp接口調(diào)騰訊云，問題就出在http連接那塊，同事當(dāng)時采用了,線上出現(xiàn)了cpu100%的問題，日志出現(xiàn)java.lang.OutOfMemoryError: GC overhead limit exceeded。
排查思路：這個其實很好定位，本來還想打印線程棧看下到底是哪個導(dǎo)致的cpu100%，一看日志直接定位到gc出問題。GC overhead limit exceeded是指gc占用了大量的cpu時間又回收不了內(nèi)存引起的，從內(nèi)存泄露去考慮，重啟服務(wù) ，啟動參數(shù)加上-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./user.hprof -verbose:gc -Xloggc:user%t.log。問題復(fù)現(xiàn)的時候獲得了堆的dump文件，然后通過Jprofile分析，發(fā)現(xiàn)有大量的http.HttpKeepAliveCache實例，占用了80%的內(nèi)存，大致定位到是由于http連接泄露。同事封裝的HttpUtil中使用了HttpsURLConnection，在讀取完數(shù)據(jù)的時候沒有關(guān)閉InputStream導(dǎo)致連接沒有關(guān)閉。
說明：GC overhead limit exceeded，默認(rèn)情況下，如果Java進(jìn)程花費(fèi)98%以上的時間執(zhí)行GC，并且每次只有不到2%的堆被恢復(fù)，則JVM拋出此錯誤。這個錯誤是parallel Scavenge 特有的
String拼接導(dǎo)致內(nèi)存溢出
公司的后臺有段時間會間歇性的卡頓，嚴(yán)重的情況下會導(dǎo)致cpu100%。在cpu100%的時候，通過top定位到進(jìn)程號，然后輸入H切換到線程，記住具體的進(jìn)程號，使用jstack打印java進(jìn)程的線程棧，jstack輸出為十六進(jìn)制，需要將top的轉(zhuǎn)換成十六進(jìn)制的然后入找線程經(jīng)常卡在哪個方法。定位到方法發(fā)現(xiàn)是查詢用戶關(guān)聯(lián)設(shè)備號的方法出問題，方法的邏輯是從數(shù)據(jù)庫查詢設(shè)備號，在內(nèi)存中以以逗號分隔拼接返回，如1,2,3。這個bug的原因是有如下：
sql出錯，導(dǎo)致查詢返回數(shù)據(jù)量很多，正常情況最多幾百個，但是異常情況有七萬個設(shè)備號
字符串拼接采用str+="1234"的形式，導(dǎo)致大量的內(nèi)存分配和回收。
運(yùn)營在點擊后臺查詢的時候發(fā)現(xiàn)沒返回，點掉就重新點，導(dǎo)致服務(wù)器多個線程卡在這個方法造成cpu100%。解決完sql，改用StringBuilder問題解決。
堆內(nèi)存占用過大
我們的一個服務(wù)程序，老年代設(shè)置了10g，新生代2g，偶會會出現(xiàn)內(nèi)存溢出的線程，通過分析內(nèi)存發(fā)現(xiàn)deal數(shù)據(jù)占用了大量內(nèi)存，最高可達(dá)9.4g。
堆數(shù)據(jù)：
問題代碼：
優(yōu)化后堆數(shù)據(jù)：
優(yōu)化后降低了老年代改為4g，大大降低了Jvm的堆的大小，16g機(jī)器現(xiàn)在可部署兩個實例，且Full Gc穩(wěn)定在一天一次，Young Gc 5s一次，均處正常。
CPU占用高問題
最近在分析拍賣程序時，發(fā)現(xiàn)com.miaozhen.bazaro.deal.PreferredDealFilterService#filter方法占用了90%的cpu時間。
cpu熱點圖：
問題代碼：
分析該方法的時長：
查看耗時deal數(shù)據(jù)
aerospike線程阻塞導(dǎo)致內(nèi)存溢出問題
問題：拍賣在五點多收到網(wǎng)站推送數(shù)據(jù)的時候發(fā)生OOM。
查看日志發(fā)現(xiàn)，有很多關(guān)于線程阻塞的報錯，是讀取aerospike卡住導(dǎo)致。報錯如下：
觀察gc分析結(jié)果：
可以看到本來堆內(nèi)存始終穩(wěn)定在一個水平，在一個時間點之后，堆內(nèi)存開始穩(wěn)步上漲，十分符合內(nèi)存泄漏的特征。
觀察堆內(nèi)存數(shù)據(jù)：
注：這個堆內(nèi)存不是當(dāng)時，當(dāng)時的堆內(nèi)存沒找到，占比是類似的。這個圖內(nèi)存優(yōu)化之后的，所以老年代只有4g。
可以看到其中OrderedExecutor占用了大量的內(nèi)存，這個數(shù)據(jù)接口是用來存放http請求的接口。
總結(jié)：
晚上九點40線程阻塞，但是請求的任務(wù)不停地往他的tasks里面放，十分鐘后grafana監(jiān)控顯示上升了16%的超時率(六個verticle掛了一個)，從4%到20%。
查看內(nèi)存監(jiān)控圖，9點40開始內(nèi)存上升，不再回收，最終存了2900萬個tasks，一個線程占用了10g內(nèi)存，到晚上11.15左右日志出現(xiàn)大量的空指針和超時，十分鐘后監(jiān)控圖顯示全部超時，gc監(jiān)控顯示大量full gc，因為內(nèi)存不夠大量的gc占用了進(jìn)程cpu時間。，5點多的時候推送物料，服務(wù)器內(nèi)存溢出。
參考資料：
問題
什么樣的代碼算是耗時的代碼，或者說耗時代碼的特征是什么
jvm一個線程發(fā)生OOM會導(dǎo)致JVM掛掉嗎
內(nèi)存問題會導(dǎo)致cpu飆高嗎
總結(jié)
以上是生活随笔為你收集整理的arthas 排查内存溢出_Java程序线上故障排查的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： uboot启动流程概述_Alibaba
- 下一篇： java web应用开发_Java We