arthas 排查内存溢出_Java程序线上故障排查
這篇文章是在公司做了不少的線上Java服務故障排查和優(yōu)化之后的一個總結，可以作為一個工具清單，在分析問題的時候需要有整體思路：全局觀，先從系統層面入手，大致定位方向(內存，cpu，磁盤，網絡)，然后再去分析具體的進程。
一、Linux
內存和cpu
內存和cpu問題是出問題最多的一個點，因為有些命令如top同時可以觀察到內存和cpu所以放在一起。
top命令
常用參數： -H 打印具體的線程， -p 打印某個進程 進入后 按數字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
我一般重點關注的指標有：
%Cpu(s): 5.1 us, 3.4 sy, 0.0 wa
這里可以非常直觀的看到當前cpu的負載情況，us用戶cpu占用時間，sy是系統調用cpu占用時間，wa是cpu等待io的時間，前面兩個比較直觀，但是第三個其實也很重要，如果wa很高，那么你就該重點關注下磁盤的負載了，尤其是像mysql這種服務器。
load average: 0.08, 0.26, 0.19
cpu任務隊列的負載，這個隊列包括正在運行的任務和等待運行的任務，三個數字分別是1分鐘、5分鐘和15分鐘的平均值。這個和cpu占用率一般是正相關的，反應的是用戶代碼，如果超過了內核數，表示系統已經過載。也就是說如果你是8核，那么這個數字小于等于8的負載都是沒問題的，我看網上的建議一般這個值不要超過ncpu*2-2為好。
KiB Mem : 985856 total, 81736 free, 646360 used, 257760 buff/cache
內存占用情況，total總內存，free空余內存， used已經分配內存，buff/cache塊設備和緩沖區(qū)占用的內存，因為Linux的內存分配，如果有剩余內存，他就會將內存用于cache，這樣可以較少磁盤的讀寫提高效率，如果有應用申請內存，buff/cache這部分內存也是可用的，所以正真的剩余內存應該是free+buff/cache
swap
線上服務器一般都是禁用狀態(tài)，所以不用看這項。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
這一欄主要是看進程的詳情，重點是%CPU %MEM，上面看的是整個服務器的負載，這里是每個進程的負載。還有看看S這個指標，這個代碼了進程的狀態(tài)，有時候有些進程會出現T(暫停)這個狀態(tài)。
網絡
ss
netstat的高性能版，參數都基本一致
常用參數： -n 打印數字端口號 -t tcp連接 -l 監(jiān)聽端口 -a 所有端口 -p 進程號 -s 打印統計信息
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過高，連接數過高等情況
然后使用ss -ntap|grep 進程號 or 端口號查看進程的連接
ping
查看時延和丟包情況
mtr
查看丟包請求
磁盤
磁盤問題在mysql服務器中非常常見，很多時候mysql服務器的CPU不高但是卻出現慢查詢日志飆升，就是因為磁盤出現了瓶頸。還有mysql的備份策略，如果沒有監(jiān)控磁盤空間，可能出現磁盤滿了服務不可用的現象。
**iostat命令 **
常用參數： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個幾秒刷新 顯示次數
這個是我查看磁盤負載的主要工具，也可以顯示cpu的負載，不過我一般用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
我一般重點關注的指標有：
rkB/s和wkB/s: 分別對應讀寫速度
avgqu-sz: 讀寫隊列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時間(毫秒)，分別是讀寫，讀和寫三個平均值。這個時間都包括在隊列中等待的時間和實際處理讀寫請求的時間，還有svctm這個參數，他說的是實際處理讀寫請求的時間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經廢棄，所以一般我看的是這三個。
%util: 這個參數直觀的看磁盤的負載情況，我首先看的就是這個參數。和top的wa命令有關聯。
df
查看文件系統的容量
常用參數： -h 友好的單位 如Kb，Mb等
du
統計具體的文件大小
常用參數： -h 友好的單位 如Kb，Mb等 -s 總計，而不是進入每個子目錄分別統計
場景：例如系統磁盤空間不足時，先通過df命令定位到具體的掛載目錄，在進去掛載目錄后，使用
du -sh *查看各個文件或者子目錄的大小定位具體文件
這里還有l(wèi)s命令，可以通過加-h和-S(按大小排序)
iostat命令
常用參數： -k 用kb為單位 -d 監(jiān)控磁盤 -x顯示詳情 num count 每個幾秒刷新 顯示次數
這個是我查看磁盤負載的主要工具，也可以顯示cpu的負載，不過我一般用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
我一般重點關注的指標有：
rkB/s和wkB/s: 分別對應讀寫速度
avgqu-sz: 讀寫隊列的平均請求長度，可以類比top命令的load average
await r_await w_await: io請求的平均時間(毫秒)，分別是讀寫，讀和寫三個平均值。這個時間都包括在隊列中等待的時間和實際處理讀寫請求的時間，還有svctm這個參數，他說的是實際處理讀寫請求的時間，照理來講w_await肯定是大于svctm的，但是我在線上看到有w_await小于svctm的情況，不知道是什么原因。我看iostat的man手動中說svctm已經廢棄，所以一般我看的是這三個。
%util: 這個參數直觀的看磁盤的負載情況，我首先看的就是這個參數。和top的wa命令有關聯。
lsof
列出當前系統打開文件，因為在linux下一切皆是文件，連接，硬件等均被描述為文件，所以這個命令也十分有用。
常用參數：
-p 查看某個進程的文件
直接加文件名 查看哪些進程打開了文件
+d 目錄 查看哪些進程打開了目錄以及下面的文件(不遞歸，+D是遞歸)
Sar
最后補充一個sar(System Activity Reporter)命令，如果系統沒有一個良好的監(jiān)控，那么這個命令對于排查問題是很好的補充，很多時候去排查問題的時候發(fā)現問題已經沒了，可以通過這個命令查看系統的活動情況，比如各個時間段cpu情況，內存情況。
常用參數：
-r 內存信息
-q loader信息，運行隊列情況
-u cpu信息
-W Swap換頁情況
/proc文件系統
/proc是個虛擬文件系統，是內核的一些數據，很多l(xiāng)inux命令的都是通過解析/proc文件系統實現的，每個進程都會有一個以pid為目錄名的子目錄存在，通過解析/proc下的進程目錄可以得到很多進程的設置信息和資源占用信息等。
這里簡單說個排查過的問題，當時我們線上有個服務，正常ssh登錄的情況下,我們設置了ulimit中的open files為(進程可打開的最大描述符數量)100000，但是有一次在服務的日志中發(fā)現有報錯說文件描述符不夠用。所以
二、JVM
java -XX:+PrintFlagsInitial 可以查看所以的jvm默認參數，其中帶有manageable表示運行時可以動態(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內存結構
堆內存結構：
java8元空間改動：
java 7種垃圾收集器：
常見搭配：
java8默認：Parallel Scavenge和 Parallel Old
低延遲：ParNew和CMS
java8以后可以直接使用G1，參數比較簡單
ParNew
Serial的并行版本
Parallel Scavenge
注重的是吞吐量，吞吐量=運行用戶代碼時間/(運行用戶代碼時間+垃圾收集時間)，其具有自適應的特性
控制最大垃圾收集停頓時間的-XX:MaxGCPauseMillis參數
MaxGCPauseMillis參數允許的值是一個大于0的毫秒數，收集器將盡力保證內存回收花費的時間不超過設定值。不過大家不要異想天開地認為如果把這個參數的值設置得稍小一點就能使得系統的垃圾收集速度變得更快，GC停頓時間縮短是以犧牲吞吐量和新生代空間來換取的：系統把新生代調小一些，收集300MB新生代肯定比收集500MB快吧，這也直接導致垃圾收集發(fā)生得更頻繁一些，原來10秒收集一次、每次停頓100毫秒，現在變成5秒收集一次、每次停頓70毫秒。停頓時間的確在下降，但吞吐量也降下來了。
直接設置吞吐量大小的 -XX:GCTimeRatio參數
GCTimeRatio參數的值應當是一個大于0小于100的整數，也就是垃圾收集時間占總時間的比率。如果把此參數設置為19，那允許的最大GC時間就占總時間的5%(即1 /(1+19))，默認值為99，就是允許最大1%(即1 /(1+99))的垃圾收集時間。
UseAdaptiveSizePolicy開關參數
-XX:+UseAdaptiveSizePolicy是一個開關參數，當這個參數打開之后，就不需要手工指定新生代的大小(-Xmn)、Eden與Survivor區(qū)的比例(-XX:SurvivorRatio)、晉升老年代對象年齡(-XX:PretenureSizeThreshold)等細節(jié)參數了，虛擬機會根據當前系統的運行情況收集性能監(jiān)控信息，動態(tài)調整這些參數以提供最合適的停頓時間或最大的吞吐量，這種調節(jié)方式稱為GC自適應的調節(jié)策略(GC Ergonomics)。
說說UseAdaptiveSizePolicy參數，加了這個參數-XX:SurvivorRatio會失效，所以有些人會發(fā)現新生代比例未如自己的預期，而UseAdaptiveSizePolicy有默認是開啟的
CMS
并發(fā)垃圾收集器，注重的是時延，有分配擔保失敗的風險
CMS收集器的GC周期由6個階段組成。其中4個階段(名字以Concurrent開始的)與實際的應用程序是并發(fā)執(zhí)行的，而其他2個階段需要暫停應用程序線程。
初始標記：為了收集應用程序的對象引用需要暫停應用程序線程，該階段完成后，應用程序線程再次啟動。
并發(fā)標記：從第一階段收集到的對象引用開始，遍歷所有其他的對象引用。
并發(fā)預清理：改變當運行第二階段時，由應用程序線程產生的對象引用，以更新第二階段的結果。
重標記：由于第三階段是并發(fā)的，對象引用可能會發(fā)生進一步改變。因此，應用程序線程會再一次被暫停以更新這些變化，并且在進行實際的清理之前確保一個正確的對象引用視圖。這一階段十分重要，因為必須避免收集到仍被引用的對象。
并發(fā)清理：所有不再被應用的對象將從堆里清除掉。
并發(fā)重置：收集器做一些收尾的工作，以便下一次GC周期能有一個干凈的狀態(tài)。
-XX:CMSInitiatingOccupancyFraction=90 (jdk1.5默認值68，1.6開始默認值92，指設定CMS在對內存占用率達到70%的時候開始GC(因為CMS會有浮動垃圾,所以一般都較早啟動GC)
-XX:+UseCMSInitiatingOccupancyOnly 只是用設定的回收閾值(上面指定的70%),如果不指定,JVM僅在第一次使用設定值,后續(xù)則自動調整
-XX:+CMSScavengeBeforeRemark 在CMS GC前啟動一次ygc，目的在于減少old gen對ygc gen的引用，降低remark時的開銷
-XX:+CMSParallelRemarkEnabled 并發(fā)標記
-XX:+ExplicitGCInvokesConcurrent命令JVM無論什么時候調用系統GC(system.gc())，都執(zhí)行CMS GC，而不是Full GC
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保證當有系統GC調用時，永久代也被包括進CMS垃圾回收的范圍內
-XX：UseParNewGC 使用CMS時自動開啟，因為CMS不能和Parallel Scavenge搭配使用
上面的參數都建議開啟，CMS需要注意的一個問題就是CMSInitiatingOccupancyFraction參數，這個參數直接影響CMS回收老年代的時機，需要結合自己的業(yè)務場景來調整，一般情況下應該盡量設置大一點，但是有一個嚴重的問題，就是浮動垃圾的問題，如果CMS在并發(fā)收集的時候出現老年代不能存放晉升對象將直接進行Full GC使用Serial Old垃圾收集器,所以不能一味追求最大化，如果老年代增長比較慢，那么可以設置的稍微較大些，如果增長比較快，可以從增大新生代，調低CMSInitiatingOccupancyFraction入手
最后在提下-XX:+DisableExplicitGC ：禁用顯示gc (system.gc())這個參數，很多人因為system.gc()會導致Full gc而禁用顯示調用gc，但是這個參數最好不要禁用，現在很多服務端程序都使用了Nio，jvm為了減少內存拷貝，采用了直接內存，直接內存屬于堆外內存，java大多使用了Netty這個框架，他幫我們處理堆外內存的回收，實現的機制就是通過調用system.gc()，發(fā)起Full Gc，Full Gc會回收堆外內存，如果將system.gc()禁用，則得等到Full Gc發(fā)生才能回收堆外內存，很有可能出現堆外內存占用過高影響系統性能或者因為內存不足被系統Kill的問題。
gc日志參數
-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細日志
-XX:+PrintGCTimeStamps 輸出GC的時間戳(以基準時間的形式)
-XX:+PrintGCDateStamps 輸出GC的時間戳(以日期的形式，如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在進行GC的前后打印出堆的信息
-XX:+PrintGCApplicationStoppedTime // 輸出GC造成應用暫停的時間
-Xloggc:../logs/gc.log 日志文件的輸出路徑
-XX:+PrintTenuringDistribution 打印新生代的年齡分布(這里需要注意，如果使用的是Parallel Scavenge，那么打印的時候是沒有年齡分布信息的)
-XX:+UseGCLogFileRotation 開啟日志輪換
-XX:NumberOfGCLogFiles=5 日志保留數量
-XX:GCLogFileSize=10m 每份日志保留大小
堆參數
-Xms 最小堆大小
-Xmx 最大堆大小
-Xmn 新生代大小
-XX:SurvivorRatio 新生代中Eden區(qū)與Survivor區(qū)的比例，默認值為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日志中打印了新生代，老年代和元空間等內存信息，其中Times: user=0.02 sys=0.01, real=0.01 secs三個時間分別是用戶態(tài)的時間，內核態(tài)的時間和墻鐘時間。墻鐘時間表示真正過去的時間，而用戶態(tài)和內核態(tài)的時間則是乘了相應的cpu核心數。
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相關參數：
-agentlib:[=]
加載本機代理庫 , 例如 -agentlib:jdwp
另請參閱 -agentlib:jdwp=help
-agentpath:[=]
按完整路徑名加載本機代理庫
-javaagent:[=]
加載 Java 編程語言代理, 請參閱 java.lang.instrument
JVMTI(Java Virtual Machine Tool Interface)即指Java虛擬機工具接口，它是一套由虛擬機直接提供的 native 接口，通過這些接口，開發(fā)人員不僅調試在該虛擬機上運行的 Java 程序，還能查看它們運行的狀態(tài)，設置回調函數，控制某些環(huán)境變量(JMX)，從而優(yōu)化程序性能。Java Agent就是基于JVMTI的，所以眾多基于Java Agent的技術例如APM，遠程調試，各種性能剖析同樣是基于這個技術。
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下對應的動態(tài)庫是libinstrument.so)。
Attach機制
Jvm提供一種jvm進程間通信的能力，能讓一個進程傳命令給另外一個進程，并讓它執(zhí)行內部的一些操作，比如說我們?yōu)榱俗屃硗庖粋€jvm進程把線程dump出來，那么我們跑了一個jstack的進程，然后傳了個pid的參數，告訴它要哪個進程進行線程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是處理進程信號的線程，Attach Listener正式Attach機制處理線程。
java自帶工具
jps
查看Java進程列表
常用參數：
-l: 輸出應用程序主類完整package名稱或jar完整名稱
-m:輸出主函數傳入的參數
jmap
查看JVM堆的情況
常用參數：
-heap
-dump 這個命令還有兩個常用參數
live 只dump存活對象，會導致GC
file=file dump文件名
示例：jmap -dump:live,file=heap.dump
這里有兩點，一方面需要注意live會導致GC，有時候在查問題的時候可能不是你預期的效果，一般查內存問題時不加這個選項，另外dump文件如果比較大，可以先壓縮在傳回本地
jstack
查看JVM的堆棧情況，監(jiān)測死鎖等
這個命令比較簡單，一般不用加什么參數，有時候JVM沒響應時可以加-F參數。一般這個命令可以結合top，在top定位到占用cpu高的線程后，在具體在Jstack打印的堆棧中查看線程，有時候也需要多次打印堆棧來進行對比
jstat
查看JVM gc信息，觀察JVM的GC活動
常用參數： -gccause 這個參數包含了-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
查看設置的JVM參數和啟動時的命令行參數，還可以動態(tài)修改JVM參數
常用參數
-flags 查看jvm參數值
-sysprops 查看系統屬性值
示例：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遠程調試，需要jvm啟動時加參數：-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005
遠程調試非常有用，有時候測試環(huán)境很難復現時，可以用通過遠程調試查看線程數據
三、三方工具
jprofile
CPU性能分析
抽樣：每隔一段時間，獲取線程棧，分析各個棧上出現的方法的次數
優(yōu)點：性能高
缺點： 不適合做精確的分析
適用范圍：尋找程序的執(zhí)行熱點，cpu密集型
指令插入：使用增強的技術修改java class的字節(jié)碼，在函數的出入口增加埋點
優(yōu)點：數據準確
缺點：導致jvm內聯優(yōu)化失效，性能低
適用范圍：分析具體耗時路徑的各個執(zhí)行時間，io密集型
一般先使用抽樣在定位到大致的范圍，然后使用指令插入分析具體代碼執(zhí)行路徑中的耗時，jprofile可以通過過濾只對指定類進行增強
Thread Status：選擇線程統計狀態(tài)，Runnable顯示的是cpu時間，不包含sleep這種時間一般都是這個模式。還可以使用IO Net模式分析io等待，Wait分析鎖競爭模式
Call tree filters ：調用樹過濾：用于過濾不需要的類，例如你使用web框架，棧中起始的方法都是框架中的代碼，最后才是你的業(yè)務代碼，這時候可以使用Call tree filters來過濾不需要的類型，減少統計造成的性能開銷
內存剖析
分析內存泄漏的利器，主要是看內存中內存占比和大對象。很多時候如果有內存泄漏基本都是以為某些類型的對象占用了大頭。
arthas (類似btrace的工具)
Arthas 是Alibaba開源的Java診斷工具。線上debug的工具，很多時候因為性能和安全等原因我們不能直接遠程調試線上的jvm，這時候我們可以使用arthas來查看內存的數據，方法調用情況，打印日志信息等。
比較常用的：
watch 看方法調用情況 -c 統計周期，默認值為120秒
monitor 統計方法調用信息
getstatic 查看靜態(tài)變量
logger 查看和修改logger
trace 方法內部調用路徑，并輸出方法路徑上的每個節(jié)點上耗時
示例：
monitor -c 5 com.miaozhen.bazaro.deal.PreferredDealFilterService filter
watch com.miaozhen.bazaro.share.manager.util.DealManager getDspToDealsByPid "returnObj"
gceasy
四、實際案例
連接泄漏
場景描述：我們公司的用戶服務對接了第三方騰訊云通信服務，在用戶注冊的時候我們需要走http接口調騰訊云，問題就出在http連接那塊，同事當時采用了,線上出現了cpu100%的問題，日志出現java.lang.OutOfMemoryError: GC overhead limit exceeded。
排查思路：這個其實很好定位，本來還想打印線程棧看下到底是哪個導致的cpu100%，一看日志直接定位到gc出問題。GC overhead limit exceeded是指gc占用了大量的cpu時間又回收不了內存引起的，從內存泄露去考慮，重啟服務 ，啟動參數加上-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./user.hprof -verbose:gc -Xloggc:user%t.log。問題復現的時候獲得了堆的dump文件，然后通過Jprofile分析，發(fā)現有大量的http.HttpKeepAliveCache實例，占用了80%的內存，大致定位到是由于http連接泄露。同事封裝的HttpUtil中使用了HttpsURLConnection，在讀取完數據的時候沒有關閉InputStream導致連接沒有關閉。
說明：GC overhead limit exceeded，默認情況下，如果Java進程花費98%以上的時間執(zhí)行GC，并且每次只有不到2%的堆被恢復，則JVM拋出此錯誤。這個錯誤是parallel Scavenge 特有的
String拼接導致內存溢出
公司的后臺有段時間會間歇性的卡頓，嚴重的情況下會導致cpu100%。在cpu100%的時候，通過top定位到進程號，然后輸入H切換到線程，記住具體的進程號，使用jstack打印java進程的線程棧，jstack輸出為十六進制，需要將top的轉換成十六進制的然后入找線程經常卡在哪個方法。定位到方法發(fā)現是查詢用戶關聯設備號的方法出問題，方法的邏輯是從數據庫查詢設備號，在內存中以以逗號分隔拼接返回，如1,2,3。這個bug的原因是有如下：
sql出錯，導致查詢返回數據量很多，正常情況最多幾百個，但是異常情況有七萬個設備號
字符串拼接采用str+="1234"的形式，導致大量的內存分配和回收。
運營在點擊后臺查詢的時候發(fā)現沒返回，點掉就重新點，導致服務器多個線程卡在這個方法造成cpu100%。解決完sql，改用StringBuilder問題解決。
堆內存占用過大
我們的一個服務程序，老年代設置了10g，新生代2g，偶會會出現內存溢出的線程，通過分析內存發(fā)現deal數據占用了大量內存，最高可達9.4g。
堆數據：
問題代碼：
優(yōu)化后堆數據：
優(yōu)化后降低了老年代改為4g，大大降低了Jvm的堆的大小，16g機器現在可部署兩個實例，且Full Gc穩(wěn)定在一天一次，Young Gc 5s一次，均處正常。
CPU占用高問題
最近在分析拍賣程序時，發(fā)現com.miaozhen.bazaro.deal.PreferredDealFilterService#filter方法占用了90%的cpu時間。
cpu熱點圖：
問題代碼：
分析該方法的時長：
查看耗時deal數據
aerospike線程阻塞導致內存溢出問題
問題：拍賣在五點多收到網站推送數據的時候發(fā)生OOM。
查看日志發(fā)現，有很多關于線程阻塞的報錯，是讀取aerospike卡住導致。報錯如下：
觀察gc分析結果：
可以看到本來堆內存始終穩(wěn)定在一個水平，在一個時間點之后，堆內存開始穩(wěn)步上漲，十分符合內存泄漏的特征。
觀察堆內存數據：
注：這個堆內存不是當時，當時的堆內存沒找到，占比是類似的。這個圖內存優(yōu)化之后的，所以老年代只有4g。
可以看到其中OrderedExecutor占用了大量的內存，這個數據接口是用來存放http請求的接口。
總結：
晚上九點40線程阻塞，但是請求的任務不停地往他的tasks里面放，十分鐘后grafana監(jiān)控顯示上升了16%的超時率(六個verticle掛了一個)，從4%到20%。
查看內存監(jiān)控圖，9點40開始內存上升，不再回收，最終存了2900萬個tasks，一個線程占用了10g內存，到晚上11.15左右日志出現大量的空指針和超時，十分鐘后監(jiān)控圖顯示全部超時，gc監(jiān)控顯示大量full gc，因為內存不夠大量的gc占用了進程cpu時間。，5點多的時候推送物料，服務器內存溢出。
參考資料：
問題
什么樣的代碼算是耗時的代碼，或者說耗時代碼的特征是什么
jvm一個線程發(fā)生OOM會導致JVM掛掉嗎
內存問題會導致cpu飆高嗎
總結
以上是生活随笔為你收集整理的arthas 排查内存溢出_Java程序线上故障排查的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： uboot启动流程概述_Alibaba
- 下一篇： rf中resourceid_解决VC++