Java程序線上故障排查
目錄html
總體思路：全局觀，先從系統層面入手，大體定位方向（內存，cpu，磁盤，網絡），而後再去分析具體的進程。java
1、Linux
內存和cpu
內存和cpu問題是出問題最多的一個點，由於有些命令如top同時能夠觀察到內存和cpu因此放在一塊兒。mysql
top命令linux
經常使用參數： -H 打印具體的線程， -p 打印某個進程 進入後 按數字1 能夠切換cpu的圖形看有幾個核android
下面是個人測試環境shell:ios
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
我通常重點關注的指標有：c++
%Cpu(s): 5.1 us, 3.4 sy, 0.0 wagit
這裏能夠很是直觀的看到當前cpu的負載狀況，us用戶cpu佔用時間，sy是系統調用cpu佔用時間，wa是cpu等待io的時間，前面兩個比較直觀，可是第三個其實也很重要，若是wa很高，那麼你就該重點關注下磁盤的負載了，尤爲是像mysql這種服務器。github
load average: 0.08, 0.26, 0.19web
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塊設備和緩衝區佔用的內存，由於Linux的內存分配，若是有剩餘內存，他就會將內存用於cache，這樣能夠較少磁盤的讀寫提升效率，若是有應用申請內存，buff/cache這部份內存也是可用的，因此正真的剩餘內存應該是free+buff/cache
swap
線上服務器通常都是禁用狀態，因此不用看這項。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
這一欄主要是看進程的詳情，重點是%CPU %MEM，上面看的是整個服務器的負載，這裏是每一個進程的負載。還有看看S這個指標，這個代碼了進程的狀態，有時候有些進程會出現T（暫停）這個狀態。
網絡
ss
netstat的高性能版，參數都基本一致
經常使用參數： -n 打印數字端口號 -t tcp鏈接 -l 監聽端口 -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的備份策略，若是沒有監控磁盤空間，可能出現磁盤滿了服務不可用的現象。
iostat命令
經常使用參數： -k 用kb爲單位 -d 監控磁盤 -x顯示詳情 num count 每一個幾秒刷新 顯示次數
這個是我查看磁盤負載的主要工具，也能夠顯示cpu的負載，不過我通常用iostat -kdx 2 10,下面是我測試環境執行狀況：
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 *查看各個文件或者子目錄的大小定位具體文件
這裏還有ls命令，能夠經過加-h和-S（按大小排序）
iostat命令
經常使用參數： -k 用kb爲單位 -d 監控磁盤 -x顯示詳情 num count 每一個幾秒刷新 顯示次數
這個是我查看磁盤負載的主要工具，也能夠顯示cpu的負載，不過我通常用iostat -kdx 2 10,下面是我測試環境執行狀況：
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)命令，若是系統沒有一個良好的監控，那麼這個命令對於排查問題是很好的補充，不少時候去排查問題的時候發現問題已經沒了，能夠經過這個命令查看系統的活動狀況，好比各個時間段cpu狀況，內存狀況。
經常使用參數：
- -r 內存信息
- -q loader信息，運行隊列狀況
- -u cpu信息
- -W Swap換頁狀況
/proc文件系統
/proc是個虛擬文件系統，是內核的一些數據，不少linux命令的都是經過解析/proc文件系統實現的，每一個進程都會有一個以pid爲目錄名的子目錄存在，經過解析/proc下的進程目錄能夠獲得不少進程的設置信息和資源佔用信息等。
這裏簡單說個排查過的問題，當時咱們線上有個服務，正常ssh登陸的狀況下,咱們設置了ulimit中的open files爲（進程可打開的最大描述符數量）100000，可是有一次在服務的日誌中發現有報錯說文件描述符不夠用。因此
2、JVM
java -XX:+PrintFlagsInitial 能夠查看因此的jvm默認參數，其中帶有manageable表示運行時能夠動態修改。
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快吧，這也直接致使垃圾收集發生得更頻繁一些，原來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區的比例（-XX:SurvivorRatio）、晉升老年代對象年齡（-XX:PretenureSizeThreshold）等細節參數了，虛擬機會根據當前系統的運行狀況收集性能監控信息，動態調整這些參數以提供最合適的停頓時間或最大的吞吐量，這種調節方式稱爲GC自適應的調節策略（GC Ergonomics）。
說說UseAdaptiveSizePolicy參數，加了這個參數-XX:SurvivorRatio會失效，因此有些人會發現新生代比例未如本身的預期，而UseAdaptiveSizePolicy有默認是開啓的
CMS
併發垃圾收集器，注重的是時延，有分配擔保失敗的風險
CMS收集器的GC週期由6個階段組成。其中4個階段(名字以Concurrent開始的)與實際的應用程序是併發執行的，而其餘2個階段須要暫停應用程序線程。
初始標記：爲了收集應用程序的對象引用須要暫停應用程序線程，該階段完成後，應用程序線程再次啓動。
併發標記：從第一階段收集到的對象引用開始，遍歷全部其餘的對象引用。
併發預清理：改變當運行第二階段時，由應用程序線程產生的對象引用，以更新第二階段的結果。
重標記：因爲第三階段是併發的，對象引用可能會發生進一步改變。所以，應用程序線程會再一次被暫停以更新這些變化，而且在進行實際的清理以前確保一個正確的對象引用視圖。這一階段十分重要，由於必須避免收集到仍被引用的對象。
併發清理：全部再也不被應用的對象將從堆裏清除掉。
併發重置：收集器作一些收尾的工做，以便下一次GC週期能有一個乾淨的狀態。
- -XX:CMSInitiatingOccupancyFraction=90 （jdk1.5默認值68，1.6開始默認值92，指設定CMS在對內存佔用率達到70%的時候開始GC(由於CMS會有浮動垃圾,因此通常都較早啓動GC)
- -XX:+UseCMSInitiatingOccupancyOnly 只是用設定的回收閾值(上面指定的70%),若是不指定,JVM僅在第一次使用設定值,後續則自動調整
- -XX:+CMSScavengeBeforeRemark 在CMS GC前啓動一次ygc，目的在於減小old gen對ygc gen的引用，下降remark時的開銷
- -XX:+CMSParallelRemarkEnabled 併發標記
- -XX:+ExplicitGCInvokesConcurrent命令JVM不管何時調用系統GC（system.gc()），都執行CMS GC，而不是Full GC
- -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses保證當有系統GC調用時，永久代也被包括進CMS垃圾回收的範圍內
- -XX：UseParNewGC 使用CMS時自動開啓，由於CMS不能和Parallel Scavenge搭配使用
上面的參數都建議開啓，CMS須要注意的一個問題就是CMSInitiatingOccupancyFraction參數，這個參數直接影響CMS回收老年代的時機，須要結合本身的業務場景來調整，通常狀況下應該儘可能設置大一點，可是有一個嚴重的問題，就是浮動垃圾的問題，若是CMS在併發收集的時候出現老年代不能存放晉升對象將直接進行Full GC使用Serial Old垃圾收集器,因此不能一味追求最大化，若是老年代增加比較慢，那麼能夠設置的稍微較大些，若是增加比較快，能夠從增大新生代，調低CMSInitiatingOccupancyFraction入手
最後在提下-XX:+DisableExplicitGC ：禁用顯示gc （system.gc()）這個參數，不少人由於system.gc()會致使Full gc而禁用顯示調用gc，可是這個參數最好不要禁用，如今不少服務端程序都使用了Nio，jvm爲了減小內存拷貝，採用了直接內存，直接內存屬於堆外內存，java大多使用了Netty這個框架，他幫咱們處理堆外內存的回收，實現的機制就是經過調用system.gc()，發起Full Gc，Full Gc會回收堆外內存，若是將system.gc()禁用，則得等到Full Gc發生才能回收堆外內存，頗有可能出現堆外內存佔用太高影響系統性能或者由於內存不足被系統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區與Survivor區的比例，默認值爲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三個時間分別是用戶態的時間，內核態的時間和牆鍾時間。牆鍾時間表示真正過去的時間，而用戶態和內核態的時間則是乘了相應的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:<jar 路徑>[=<選項>]
加載 Java 編程語言代理, 請參閱 java.lang.instrument
JVMTI(Java Virtual Machine Tool Interface)即指Java虛擬機工具接口，它是一套由虛擬機直接提供的 native 接口，經過這些接口，開發人員不只調試在該虛擬機上運行的 Java 程序，還能查看它們運行的狀態，設置回調函數，控制某些環境變量(JMX)，從而優化程序性能。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++編寫的動態庫，-agentlib和-javaagent是一個instrument的JVMTIAgent（linux下對應的動態庫是libinstrument.so）。
Attach機制
Jvm提供一種jvm進程間通訊的能力，能讓一個進程傳命令給另一個進程，並讓它執行內部的一些操做，好比說咱們爲了讓另一個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流程：
Jstack源碼：
https://android.googlesource.com/platform/libcore/+/0ebbfbdbca73d6261a77183f68e1f3e56c339f9f/ojluni/src/main/java/sun/tools/jstack/JStack.java
查看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 <pid>
這裏有兩點，一方面須要注意live會致使GC，有時候在查問題的時候可能不是你預期的效果，通常查內存問題時不加這個選項，另外dump文件若是比較大，能夠先壓縮在傳回本地
jstack
查看JVM的堆棧狀況，監測死鎖等
這個命令比較簡單，通常不用加什麼參數，有時候JVM沒響應時能夠加-F參數。通常這個命令能夠結合top，在top定位到佔用cpu高的線程後，在具體在Jstack打印的堆棧中查看線程，有時候也須要屢次打印堆棧來進行對比
jstat
查看JVM gc信息，觀察JVM的GC活動
經常使用參數： -gccause 這個參數包含了-gcutil的信息多了一個gc緣由
示例： jstat -gccause <pid> 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參數和啓動時的命令行參數，還能夠動態修改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
遠程調試很是有用，有時候測試環境很難復現時，能夠用經過遠程調試查看線程數據
3、三方工具
jprofile
CPU性能分析
抽樣：每隔一段時間，獲取線程棧，分析各個棧上出現的方法的次數
優勢：性能高
缺點： 不適合作精確的分析
適用範圍：尋找程序的執行熱點，cpu密集型
指令插入：使用加強的技術修改java class的字節碼，在函數的出入口增長埋點
優勢：數據準確
缺點：致使jvm內聯優化失效，性能低
適用範圍：分析具體耗時路徑的各個執行時間，io密集型
通常先使用抽樣在定位到大體的範圍，而後使用指令插入分析具體代碼執行路徑中的耗時，jprofile能夠經過過濾只對指定類進行加強
- Thread Status：選擇線程統計狀態，Runnable顯示的是cpu時間，不包含sleep這種時間通常都是這個模式。還可使用IO Net模式分析io等待，Wait分析鎖競爭模式
- Call tree filters ：調用樹過濾：用於過濾不須要的類，例如你使用web框架，棧中起始的方法都是框架中的代碼，最後纔是你的業務代碼，這時候可使用Call tree filters來過濾不須要的類型，減小統計形成的性能開銷
內存剖析
分析內存泄漏的利器，主要是看內存中內存佔比和大對象。不少時候若是有內存泄漏基本都是覺得某些類型的對象佔用了大頭。
arthas （相似btrace的工具）
Arthas 是Alibaba開源的Java診斷工具。線上debug的工具，不少時候由於性能和安全等緣由咱們不能直接遠程調試線上的jvm，這時候咱們可使用arthas來查看內存的數據，方法調用狀況，打印日誌信息等。
比較經常使用的：
- watch 看方法調用狀況 -c 統計週期，默認值爲120秒
- monitor 統計方法調用信息
- getstatic 查看靜態變量
- logger 查看和修改logger
- trace 方法內部調用路徑，並輸出方法路徑上的每一個節點上耗時
示例：
monitor -c 5 com.miaozhen.bazaro.deal.PreferredDealFilterService filterwatch com.miaozhen.bazaro.share.manager.util.DealManager getDspToDealsByPid "returnObj"
gceasy
https://gceasy.io/ 一個在線分析gc日誌的網站，
4、實際案例
鏈接泄漏
場景描述：咱們公司的用戶服務對接了第三方騰訊雲通訊服務，在用戶註冊的時候咱們須要走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分析，發現有大量的http.HttpKeepAliveCache實例，佔用了80%的內存，大體定位到是因爲http鏈接泄露。同事封裝的HttpUtil中使用了HttpsURLConnection，在讀取完數據的時候沒有關閉InputStream致使鏈接沒有關閉。
說明：GC overhead limit exceeded，默認狀況下，若是Java進程花費98%以上的時間執行GC，而且每次只有不到2%的堆被恢復，則JVM拋出此錯誤。這個錯誤是parallel Scavenge 特有的
String拼接致使內存溢出
公司的後臺有段時間會間歇性的卡頓，嚴重的狀況下會致使cpu100%。在cpu100%的時候，經過top定位到進程號，而後輸入H切換到線程，記住具體的進程號，使用jstack打印java進程的線程棧，jstack輸出爲十六進制，須要將top的轉換成十六進制的而後入找線程常常卡在哪一個方法。定位到方法發現是查詢用戶關聯設備號的方法出問題，方法的邏輯是從數據庫查詢設備號，在內存中以以逗號分隔拼接返回，如1,2,3。這個bug的緣由是有以下：
sql出錯，致使查詢返回數據量不少，正常狀況最多幾百個，可是異常狀況有七萬個設備號
字符串拼接採用str+="1234"的形式，致使大量的內存分配和回收。
運營在點擊後臺查詢的時候發現沒返回，點掉就從新點，致使服務器多個線程卡在這個方法形成cpu100%。解決完sql，改用StringBuilder問題解決。
堆內存佔用過大
咱們的一個服務程序，老年代設置了10g，新生代2g，偶會會出現內存溢出的線程，經過分析內存發現deal數據佔用了大量內存，最高可達9.4g。
堆數據：
問題代碼：
優化後堆數據：
優化後下降了老年代改成4g，大大下降了Jvm的堆的大小，16g機器如今可部署兩個實例，且Full Gc穩定在一天一次，Young Gc 5s一次，均處正常。
CPU佔用高問題
最近在分析拍賣程序時，發現com.miaozhen.bazaro.deal.PreferredDealFilterService#filter方法佔用了90%的cpu時間。
cpu熱點圖：
問題代碼：
分析該方法的時長：
查看耗時deal數據
aerospike線程阻塞致使內存溢出問題
問題：拍賣在五點多收到網站推送數據的時候發生OOM。
查看日誌發現，有不少關於線程阻塞的報錯，是讀取aerospike卡住致使。報錯以下：
觀察gc分析結果：
能夠看到原本堆內存始終穩定在一個水平，在一個時間點以後，堆內存開始穩步上漲，十分符合內存泄漏的特徵。
觀察堆內存數據：
注：這個堆內存不是當時，當時的堆內存沒找到，佔比是相似的。這個圖內存優化以後的，因此老年代只有4g。
能夠看到其中OrderedExecutor佔用了大量的內存，這個數據接口是用來存放http請求的接口。
總結：
晚上九點40線程阻塞，可是請求的任務不停地往他的tasks裏面放，十分鐘後grafana監控顯示上升了16%的超時率（六個verticle掛了一個），從4%到20%。
查看內存監控圖，9點40開始內存上升，再也不回收，最終存了2900萬個tasks，一個線程佔用了10g內存，到晚上11.15左右日誌出現大量的空指針和超時，十分鐘後監控圖顯示所有超時，gc監控顯示大量full gc，由於內存不夠大量的gc佔用了進程cpu時間。，5點多的時候推送物料，服務器內存溢出。
參考資料：
- Java遠程調試JDPA介紹
- JVM源碼分析之javaagent原理徹底解讀
- 深刻理解Java虛擬機（第2版）
- JVM CPU Profiler技術原理及源碼深度解析
- JVM 與 Linux 的內存關係詳解
- Oracle JDK文檔
- JProfile
- Arthas官網
- CMS收集器參數
問題
- 什麼樣的代碼算是耗時的代碼，或者說耗時代碼的特徵是什麼
- jvm一個線程發生OOM會致使JVM掛掉嗎
- 內存問題會致使cpu飆高嗎
- 1. Linux線上故障排查
- 2. JAVA 線上故障排查全套路
- 3. Java線上應用故障排查
- 4. java線上故障排查技巧-cpu
- 5. 線上故障排查（2019-12-02）
- 6. 【JVM】線上應用故障排查
- 7. 線上故障排查-CPU高問題
- 8. Arthas線上實戰：Dubbo線程池耗盡故障排查
- 9. Java線上應用故障排查之一：高CPU佔用
- 10. JAVA應用運維，線上故障排查全套路
- 更多相關文章...
- • ADO 排序 - ADO 教程
- • PHP 數組排序 - PHP教程
- • 算法總結-歸併排序
- • Java 8 Stream 教程
-
每一个你不满意的现在，都有一个你没有努力的曾经。