一、Linux
- 記憶體和cpu
- 網路
- 磁碟
- /proc檔案系統
二、JVM
- Java堆和垃圾收集器
- gc日誌分析
- JVMTI介紹
- Attach機制
- java自帶工具
三、三方工具
- jprofile
- arthas （類似btrace的工具）
- gceasy
四、實際案例
- 連線洩漏
- String拼接導致記憶體溢位
- 堆記憶體佔用過大
- CPU佔用高問題
- aerospike執行緒阻塞導致記憶體溢位問題
問題

這篇文章是在公司做了不少的線上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（暫停）這個狀態。

網路

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命令有關聯。

檢視檔案系統的容量

常用引數： -h 友好的單位如Kb，Mb等

統計具體的檔案大小

常用引數： -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 這個命令還有兩個常用引數
1. live 只dump存活物件，會導致GC
2. 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 filter
watch 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點多的時候推送物料，伺服器記憶體溢位。

參考資料：

Java遠端除錯JDPA介紹
JVM原始碼分析之javaagent原理完全解讀
深入理解Java虛擬機器（第2版）
JVM CPU Profiler技術原理及原始碼深度解析
JVM 與 Linux 的記憶體關係詳解
Oracle JDK文件
JProfile
Arthas官網
CMS收集器引數

問題

什麼樣的程式碼算是耗時的程式碼，或者說耗時程式碼的特徵是什麼
jvm一個執行緒發生OOM會導致JVM掛掉嗎
記憶體問題會導致cpu飆高嗎

相關推薦

Java程式線上故障排查

目錄一、Linux 記憶體和cpu 網路磁碟 /proc檔案系統二、JVM Java堆和垃圾收集器 gc日誌分析

mysql 線上故障排查

mysql 線上故障排查Mysql 系統報連接池滿iostatslowlogWhat’s in slow log?Mk-query-digest mk-query-digest 全面分析slow log本文出自 “李世龍” 博客，謝絕轉載！mysql 線上故障排查

dpdk-lvs的一次線上故障排查報告

本文記錄了dpdk-lvs叢集的一次線上故障排查過程，排查思路可供讀者參考。上篇文章回顧： SOAR的IDE外掛——您的貼身DBA保鏢背景我們內部基於 dpdk 自研的高效能負載均衡器 dpdk-lvs 已經在多個機房部

線上故障排查-記憶體佔用高

這篇主要分析高記憶體佔用故障的排查。搞Java開發的，經常會碰到下面兩種異常： 1、java.lang.OutOfMemoryError: PermGen space 2、java.lang.OutOfMemoryError: Java heap space 要詳細

Java執行時故障排查

最近單獨負責一個應用上線，由於經驗不足，踩了很多坑，記錄一下，方便以後檢視。剛開始我的try，catch是這樣寫的： try { mediaType = detector.detect(inputStream, metadata); par

linux下java高記憶體故障排查

搞Java開發的，經常會碰到下面兩種異常： 1、java.lang.OutOfMemoryError: PermGen space 2、java.lang.OutOfMemoryError: Java heap space 要詳細解釋這兩種異常，需要簡單重提下Java

Java線上應用故障排查之一：高CPU佔用【轉】

近期java應用，CPU使用率一直很高，經常達到100%，通過以下步驟完美解決，分享一下。方法一：轉載：http://www.linuxhot.com/java-cpu-used-high.html 1.jps 獲取Java程序的PID。 2.jstack pid

Java線上應用故障排查之一：高CPU佔用

一個應用佔用CPU很高，除了確實是計算密集型應用之外，通常原因都是出現了死迴圈。以我們最近出現的一個實際故障為例，介紹怎麼定位和解決這類問題。根據top命令，發現PID為28555的Java程序佔用CPU高達200%，出現故障。通過ps aux | gre

Java線上應用故障排查之二：高記憶體佔用

搞Java開發的，經常會碰到下面兩種異常： 1、java.lang.OutOfMemoryError: PermGen space 2、java.lang.OutOfMemoryError: Java heap space 要詳細解釋這兩種異常，需要簡單重提下J

線上Java程式佔用 CPU 過高，請說一下排查方法？

> 我是風箏，公眾號「古時的風箏」，一個兼具深度與廣度的程式設計師鼓勵師，一個本打算寫詩卻寫起了程式碼的田園碼農！文章會收錄在 [JavaNewBee](https://github.com/huzhicheng/JavaNewBee) 中，更有 Java 後端知識圖譜，從小白到大牛要走的路都在裡面。這

一卡通vip充值消費線上oracle庫服務器故障排查過程

oracle 上圖是oracle體系總架構圖今天突然公司所有終端pos機不能刷卡消費，財務室不能充值，一下很多電話打過來了，第一反應肯定數據庫出問題了，登陸到數據庫服務器，果然sqlplus連進去後就不斷提示要求輸入用戶名，彈出一下提示：ERROR:ORA-00020: maximum number of p

java線上問題排查之rocketmq

for run 排查 com yun locks nano roc work "NettyClientWorkerThread_1" #43 daemon prio=5 os_prio=0 tid=0x00007f1018010000 nid=0x83 waiting on

從一次線上故障思考 Java 問題定位思路

問題出現：現網CPU飆高，Full GC告警 CGI 服務釋出到現網後，現網機器出現了Full GC告警，同時CPU飆高99%。在優先恢復現網服務正常後，開始著手定位Full GC的問題。在現場只能夠抓到四個GC執行緒佔用了很高的CPU，無法抓到引發Full GC的執行緒。查看了服務故障期間的錯

線上應用故障排查之二：高內存占用

int tool iter net 參數 top jmap命令 eap tom 前一篇介紹了線上應用故障排查之一：高CPU占用，這篇主要分析高內存占用故障的排查。搞Java開發的，經常會碰到下面兩種異常： 1、java.lang.OutOfMemoryError: Per

IG牛皮 JVM命令-java伺服器故障排查

一、top（Linux命令）執行top命令：（檢視程序15477的詳細情況，下文用到）系統資訊（前五行）：第1行：Top 任務佇列資訊(系統執行狀態及平均負載)，與uptime命令結果相同。第1段：系統當前時間，例如：16:07:37 第2段：系統執行時間，未重啟的時

線上執行的Java應用出故障了！我慌得一匹！

線上執行的Java應用突然沒有響應、響應緩慢，程序突然消失，遇到這些情況應該如何應對呢？今天教大家如何應對線上故障！歡迎工作一到五年的Java工程師朋友們

從一次線上故障思考Java問題定位思路

問題出現：現網CPU飆高，Full GC告警 CGI 服務釋出到現網後，現網機器出現了Full GC告警，同時CPU飆高99%。在優先恢復現網服務正常後，開始著手定位Full GC的問題。在現場只能夠抓到四個GC執行緒佔用了很高的CPU，無法抓到引發Full GC的執行緒。查看了服務故障期間的錯誤日誌，發現更

linux java 線上問題排查

一、Java 服務常見線上問題所有 Java 服務的線上問題從系統表象來看歸結起來總共有四方面：CPU、記憶體、磁碟、網路。例如 CPU 使用率峰值突然飈高、記憶體溢位 (洩露)、磁碟滿了、網路流量異常、FullGC 等等問題。基於這些現象我們可以將線上問題

Kubernetes（k8s）中文文件應用程式相關的故障排查_Kubernetes中文社群

譯者：林帆這個小節將幫助讀者除錯部署在Kubernetes的應用程式執行不正常的情況。本篇並不會包含如何除錯叢集組建過程中出現錯誤的問題，這些內容在文件的下一節中進行介紹。內容提要應用程式故障排查常見問題故障診斷排查Pods的故障 Pod始終處於Pending狀態 Pod始終處於

#Java程式設計師面試碰到一段程式碼：線上等解答！網友：看不懂，下一題

作為一名程式設計師，想要有高深的技術，那麼良好的邏輯思維能力是不可或缺的！很多企業在面試程式設計師的時候，都會出一些面試題來測試面試者，看看他們技術和邏輯能力能不能達到入職的標準，其實這些題不算太難，只要有一些相關的經驗，也是可以答到關鍵點上！如果有想學習java的程式設計師，可來我們的jav

Java程式線上故障排查

一、Linux

記憶體和cpu

網路

磁碟

/proc檔案系統

二、JVM

Java堆和垃圾收集器

gc日誌分析

JVMTI介紹

Attach機制

java自帶工具

三、三方工具

jprofile

arthas （類似btrace的工具）

gceasy

四、實際案例

連線洩漏

String拼接導致記憶體溢位

堆記憶體佔用過大

CPU佔用高問題

aerospike執行緒阻塞導致記憶體溢位問題

問題

相關推薦