目錄
這篇文章是在公司做了不少的線上Java服務故障排查和優化之後的一個總結，可以作為一個工具清單，在分析問題的時候需要有整體思路：全局觀，先從系統層面入手，大致定位方向（內存，cpu，磁盤，網絡），然後再去分析具體的進程。
一、Linux
內存和cpu
內存和cpu問題是出問題最多的一個點，因為有些命令如top同時可以觀察到內存和cpu所以放在一起。
top命令
常用參數： -H 打印具體的線程， -p 打印某個進程 進入后 按数字1 可以切換cpu的圖形看有幾個核
下面是我的測試環境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塊設備和緩衝區佔用的內存，因為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，但是有一次在服務的日誌中發現有報錯說文件描述符不夠用。所以
二、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
遠程調試非常有用，有時候測試環境很難復現時，可以用通過遠程調試查看線程數據
三、三方工具
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日誌的網站，
四、實際案例
連接泄漏
場景描述：我們公司的用戶服務對接了第三方騰訊雲通信服務，在用戶註冊的時候我們需要走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點多的時候推送物料，服務器內存溢出。
參考資料：
問題
- 什麼樣的代碼算是耗時的代碼，或者說耗時代碼的特徵是什麼
- jvm一個線程發生OOM會導致JVM掛掉嗎
- 內存問題會導致cpu飆高嗎
本站聲明:網站內容來源於博客園,如有侵權,請聯繫我們,我們將及時處理
【其他文章推薦】
※想知道網站建置、網站改版該如何進行嗎?將由專業工程師為您規劃客製化網頁設計及後台網頁設計
※不管是台北網頁設計公司、台中網頁設計公司，全省皆有專員為您服務
※Google地圖已可更新顯示潭子電動車充電站設置地點!!
※帶您來看台北網站建置，台北網頁設計，各種案例分享
