Linux排查JVM問題
阿新 • • 發佈：2020-07-19
背景
通常來說當我們的Java服務出現問題時，首先需要考慮的是這個程序是不是還在執行，然後再關注這個程序所佔用的資源多少，CPU、記憶體的使用情況，從而定位到具體問題。因此，有必要對Linux伺服器中的JVM異常排查進行下記錄。
方法
1、查詢Java程序id
ps -ef|grep java
當然，如果伺服器上有多個Java程序，我們可以考慮使用top命令，然後檢視cpu和記憶體使用率最高的程序情況
top -c #引數c表示列出命令的詳細資訊
此命令展示出的資訊，各項含義可以參考：這篇文章
假設拿到的程序id 為 3907
2、jmap檢視堆使用資訊
jmap -heap 3907
拿到結果如下：
using thread-local object allocation. Mark Sweep Compact GC Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 1258291200 (1200.0MB) NewSize = 26542080 (25.3125MB) MaxNewSize = 419430400 (400.0MB) OldSize= 53149696 (50.6875MB) NewRatio = 2 SurvivorRatio = 8 MetaspaceSize = 21807104 (20.796875MB) CompressedClassSpaceSize = 1073741824 (1024.0MB) MaxMetaspaceSize = 17592186044415 MB G1HeapRegionSize = 0 (0.0MB) Heap Usage: New Generation (Eden+ 1 Survivor Space): capacity = 23986176 (22.875MB) used = 13869504 (13.22698974609375MB) free = 10116672 (9.64801025390625MB) 57.82290599385246% used Eden Space: capacity = 21364736 (20.375MB) used = 11248072 (10.726997375488281MB) free = 10116664 (9.648002624511719MB) 52.64783987969709% used From Space: capacity = 2621440 (2.5MB) used = 2621432 (2.4999923706054688MB) free = 8 (7.62939453125E-6MB) 99.99969482421875% used To Space: capacity = 2621440 (2.5MB) used = 0 (0.0MB) free = 2621440 (2.5MB) 0.0% used tenured generation: capacity = 53149696 (50.6875MB) used = 28450632 (27.13263702392578MB) free = 24699064 (23.55486297607422MB) 53.52924690293619% used 21354 interned Strings occupying 1919928 bytes.
3、通過檢視gc統計資訊來分析問題，如果gc次數比較多，那麼發生記憶體洩漏的可能性就比較大了
jstat -gcutil 3907
得到資訊如下：
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 100.00 0.00 97.85 53.53 94.62 92.74 76 0.857 2 0.227 1.083
其中各個引數的含義如下：
s0: 新生代survivor0的使用率
s1:s1的使用率
E: 新生代eden空間的使用率
O:老年代的使用率
M:元資料的空間使用率
YGC:新生代gc次數
YGCT：新生代GC總時長
FGC：full gc的次數
FGCT: full gc 的總時長
GCT: 總的gc時長
4、檢視各個類所對應的例項物件所佔用的記憶體：（分析記憶體使用飆高原因）
[root@localhost s]# jmap -histo 3907 num #instances #bytes class name ---------------------------------------------- 1: 67987 6238344 [C 2: 337475 5399600 com.boc.eureka.service.TestHeap$OOMExample 3: 12917 3820336 [I 4: 111712 3574784 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node 5: 14247 3379280 [Ljava.lang.Object; 6: 19022 1673936 java.lang.reflect.Method 7: 67576 1621824 java.lang.String 8: 46815 1498080 java.util.concurrent.ConcurrentHashMap$Node 9: 11140 1225912 java.lang.Class 10: 9775 1174376 [B 11: 18018 720720 java.util.LinkedHashMap$Entry 12: 8591 690872 [Ljava.util.HashMap$Node; 13: 214 519680 [Ljava.util.concurrent.ConcurrentHashMap$Node; 14: 8725 488600 java.util.LinkedHashMap 15: 13800 441600 java.util.HashMap$Node 16: 26304 420864 java.lang.Object 17: 17791 392920 [Ljava.lang.Class; 18: 5130 369360 java.lang.reflect.Field
... ...
5010: 1 16 sun.util.locale.provider.SPILocaleProviderAdapter
5011: 1 16 sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter
5012: 1 16 sun.util.resources.LocaleData
5013: 1 16 sun.util.resources.LocaleData$LocaleDataResourceBundleControl
從上面的結果可以看出：
num:表示編號， #instances表示例項數量，#bytes表示佔用的記憶體位元組數量，class name是對應的類名
一個類，一般也就16位元組大小，而我們的基礎資料型別，它的大小char: 2bytes，short：2bytes, int:4 bytes.long:8bytes
5、檢視程序中執行緒使用情況（分析CPU的使用飆高原因）
top -Hp 3907
上述命令將列出程序下的各個執行緒的使用情況，我們根據結果，得到使用CPU多的執行緒id
top - 21:03:44 up 54 min, 3 users, load average: 0.17, 0.22, 0.39 Threads: 61 total, 2 running, 59 sleeping, 0 stopped, 0 zombie %Cpu(s): 1.0 us, 0.0 sy, 0.0 ni, 99.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 4912604 total, 2212304 free, 1247976 used, 1452324 buff/cache KiB Swap: 3354620 total, 3354620 free, 0 used. 3371908 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3662 root 20 0 3350296 224996 13676 R 0.7 4.6 0:37.39 TaskAcceptor-ta 3684 root 20 0 3350296 224996 13676 R 0.7 4.6 0:37.34 TaskAcceptor-12 3640 root 20 0 3350296 224996 13676 S 0.3 4.6 0:01.19 Catalina-utilit 3563 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.06 java 3564 root 20 0 3350296 224996 13676 S 0.0 4.6 0:38.20 java 3565 root 20 0 3350296 224996 13676 S 0.0 4.6 0:02.71 VM Thread 3566 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.05 Reference Handl 3567 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.06 Finalizer .... .... 3657 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.09 Eureka-Eviction 3658 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.01 Eureka-MeasureR 3659 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.00 ReplicaAwareIns 3660 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.01 Eureka-MeasureR 3661 root 20 0 3350296 224996 13676 S 0.0 4.6 0:00.05 Apache-HttpClie
我們選擇id為3662的執行緒，檢視是哪個類裡面在執行任務
先將3662轉為16進位制，因為後面檢視jstack輸出的資訊，執行緒id是16進位制的
printf "%x\n" 3662
e4e
得到結果e4e
然後通過jstack檢視e4e相關的資訊
jstack -l|grep e4e
得到結果：
"TaskAcceptor-target_127.0.0.1" #21 daemon prio=5 os_prio=0 tid=0x00007f5d111de000 nid=0xe4e runnable [0x00007f5ce8597000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000cf9b82d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467) at com.netflix.eureka.util.batcher.AcceptorExecutor$AcceptorRunner.drainInputQueues(AcceptorExecutor.java:228) at com.netflix.eureka.util.batcher.AcceptorExecutor$AcceptorRunner.run(AcceptorExecutor.java:189) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - None
這樣就能分析出是哪個類裡面的哪個方法，在不斷的佔用CPU了。