JVM效能調優實踐——JVM篇
前言
在遇到實際效能問題時，除了關注系統性能指標。還要結合應用程式的系統的日誌、堆疊資訊、GClog、threaddump等資料進行問題分析和定位。關於效能指標分析可以參考前一篇JVM效能調優實踐——效能指標分析。
JVM的調優和故障處理可以使用JDK的幾個常用命令工具。因為本文是基於Docker容器內部的Springboot服務。需要調整一下docker容器的啟動引數，才可以使用jmap等工具。jmap命令需要使用Linux的Capability的PTRACE_ATTACH許可權。而Docker自1.10在預設的seccomp配置檔案中禁用了PTRACE_ATTACH。目前使用的Docker version是17.04.0-ce。支援的Capability列表可以詳看
調整Capability的方式也比較方便。可以如下直接在執行引數後面加 cap_add,cap-drop
$docker run --cap-add=ALL --cap-drop=MKNOD ...也可以在compose中增加：
cap_add:
- ALL
cap_drop:
- NET_ADMIN
- SYS_ADMINDocker容器中的服務程序
在排查問題時，一般是先通過JVM效能調優實踐——效能指標分析中的幾個命令來分析基礎的伺服器狀態和資訊。在微服務架構中，每臺伺服器部署著若干執行著服務的容器。在不能通過應用日誌或者問題現象定位問題服務時，需要找到問題容器。
先通過TOP
top - 11:45:13 up 318 days, 20:43, 2 users, load average: 0.15, 0.19, 0.18
Tasks: 172 total, 1 running, 171 sleeping, 0 stopped, 0 zombie
%Cpu(s): 3.1 us, 1.9 sy, 0.0 ni, 94.7 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st
KiB Mem: 8175392 total, 7868636 used, 306756 free, 204400 buffers 因為Docker容器中還有java程序，所以需要找到具體的父子程序id.用ps -ef命令如下所示。第二列是PID(程序ID),第三列是PPID(父程序ID)。
$ps -ef |grep java
root 6310 6293 0 May21 ? 00:00:00 /bin/sh -c java -Dcontainer.host.ip=...
root 6331 6310 2 May21 ? 00:41:51 java -Dcontainer.host.ip= -server ...
root 8482 8465 0 Apr16 ? 00:00:00 /bin/sh -c java -Dcontainer.host.ip...
root 8506 8482 1 Apr16 ? 12:40:53 java -Dcontainer.host.ip= -server...
... 省略其他資訊可以使用docker inspect檢視容器內部資訊,找到對應的容器例項的程序資訊。如下即可列印當前宿主機的所有執行的容器例項的PID,為了方便對映，可以列印對應容器名字，或者容器ID:
## 列印容器pid和容器id
$docker ps -q | xargs docker inspect --format '{{.State.Pid}}, {{.ID}}' | grep "^${PID}"
## 列印容器pid和容器name
$ docker ps -q | xargs docker inspect --format '{{.State.Pid}}, {{.Name}}' | grep "^${PID}"
6310, /service-item
31369, /gateway-api
31094, /service-resource
31025, /service-trade
30916, /service-user
16204, /service-analytics
8482, /service-financial
... 省略其他資訊
如果要分析最消耗記憶體的程序，對應的pid= 6331,其所在的docker程序id也即父程序id= 6310,可以定位出service-item服務最消耗記憶體資源。定位到服務之後，即可使用docker exec -it service-item ‘/bin/sh’檢視容器內部資訊。
JVM調優基礎命令
在容器內部，就可以進一步使用jdk提供的jps、jstack、jstat、jmap等工具來進行jvm問題排查和調優。
jps[options] [hostid]
jps主要用來輸出JVM中執行的程序狀態資訊。
- -q 輸出類名、Jar名和傳入main方法的引數
- -m 輸出傳入main方法的引數
- -l 輸出main類或Jar的全限名
- -v 輸出傳入JVM的引數
如下檢視執行的java程序資訊，列印jar名以及執行main方法傳入的引數：
/opt/app # jps -l -m
6 /opt/app/app.jar --server.port=8080
327 sun.tools.jps.Jps -l -m
jstat
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>] jstat命令可以用於持續觀察虛擬機器記憶體中各個分割槽的使用率以及GC的統計資料。vmid是Java虛擬機器ID，在Linux/Unix系統取程序ID。
如下面輸出的資訊，取樣時間間隔為1000ms，取樣5次：
/opt/app # jstat -gc 6 1000 5
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
1536.0 1536.0 1233.7 0.0 171520.0 169769.2 249344.0 57018.6 93912.0 91906.8 11264.0 10853.7 6224 47.439 5 3.423 50.863
1536.0 1536.0 1233.7 0.0 171520.0 169805.4 249344.0 57018.6 93912.0 91906.8 11264.0 10853.7 6224 47.439 5 3.423 50.863
1536.0 1536.0 0.0 1536.0 171520.0 3527.9 249344.0 60347.4 96728.0 94808.1 11520.0 11174.7 6225 47.453 5 3.423 50.876
1536.0 1536.0 0.0 1536.0 171520.0 4742.1 249344.0 60347.4 96728.0 94808.1 11520.0 11174.7 6225 47.453 5 3.423 50.876
1536.0 1536.0 0.0 1536.0 171520.0 7589.3 249344.0 60347.4 96728.0 94808.1 11520.0 11174.7 6225 47.453 5 3.423 50.876
上述各個列的含義：
- S0C、S1C、S0U、S1U：young代的Survivor 0/1區容量（Capacity）和使用量（Used）。0是FromSurvivor,1是ToSurvivor。
- EC、EU：Eden區容量和使用量
- OC、OU：年老代容量和使用量
- MC、MU：元資料區（Metaspace）已經committed的記憶體空間和使用量
- CCSC、CCSU：壓縮Class（Compressed class space）committed的記憶體空間和使用量。
- YGC、YGT：young代GC次數和GC耗時
- FGC、FGCT：Full GC次數和Full GC耗時
- GCT：GC總耗時
可以通過分割槽佔用量上看到，在第2-3秒之間發生了一次YGC。YGC次數+1，並且Survivor from區的記憶體空間從1233.7->0,Survivor from從0->1536。Eden區也釋放了很多記憶體空間。其他變化的空間佔用也有元資料區以及元資料區的壓縮Class區。Compressed class space也是元資料區的一部分，預設是1G,也可以關閉。具體的jvm8記憶體分佈不再詳述。下一篇GC優化會再展開整理下。
如果只看gc的總統計資訊，也可以用jstat -gcutil vmid查詢：
/opt/app # jstat -gcutil 6
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 73.76 24.20 98.02 97.00 6225 47.453 5 3.423 50.876 jmap [option] pid
jmap可以用來檢視堆記憶體的使用詳情。記憶體各個分割槽可以通過jmap -heap pid來檢視。得到的輸出如下：
$jmap -heap 6
Attaching to process ID 6, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.121-b13
using thread-local object allocation.
Parallel GC with 2 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 536870912 (512.0MB)
NewSize = 44564480 (42.5MB)
MaxNewSize = 178782208 (170.5MB)
OldSize = 89653248 (85.5MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 170393600 (162.5MB)
used = 99020080 (94.43290710449219MB)
free = 71373520 (68.06709289550781MB)
58.11255821814904% used
From Space:
capacity = 4194304 (4.0MB)
used = 786432 (0.75MB)
free = 3407872 (3.25MB)
18.75% used
To Space:
capacity = 4194304 (4.0MB)
used = 0 (0.0MB)
free = 4194304 (4.0MB)
0.0% used
PS Old Generation
capacity = 255328256 (243.5MB)
used = 65264912 (62.24147033691406MB)
free = 190063344 (181.25852966308594MB)
25.561178783126927% used
39531 interned Strings occupying 4599760 bytes.Heap Configuration是堆記憶體的配置資訊。可以通過執行引數改變。一般通過分析記憶體分佈和使用情況以及GC資訊，可以針對不同的應用不斷調整到合適的堆記憶體分割槽配置。
Heap Usage可以看堆記憶體實時的佔用情況。
使用jmap -histo[:live] pid檢視堆記憶體中的物件的數目，佔用記憶體（單位是byte），如果帶上live則只統計活物件，如下：
/opt/app/logs # jmap -histo:live 6 | more
num #instances #bytes class name
----------------------------------------------
1: 127610 19132008 [C
2: 6460 4074512 [B
3: 37041 3259608 java.lang.reflect.Method
4: 125182 3004368 java.lang.String
5: 86616 2771712 java.util.concurrent.ConcurrentHashMap$Node
6: 70783 2265056 java.util.HashMap$Node
7: 17686 1967496 java.lang.Class
8: 15834 1448440 [Ljava.util.HashMap$Node;
9: 35360 1414400 java.util.LinkedHashMap$Entry
10: 21948 1231624 [Ljava.lang.Object;
11: 9940 1165728 [I
12: 986 1064480 [Ljava.util.concurrent.ConcurrentHashMap$Node;
13: 18685 1046360 java.util.LinkedHashMap
14: 30351 971232 java.lang.ref.WeakReference
15: 50340 805440 java.lang.Object
16: 13490 539600 java.lang.ref.SoftReference
17: 17705 513768 [Ljava.lang.String;
18: 18781 450744 org.springframework.security.access.method.DelegatingMethodSecurityMetadataSource$DefaultCacheKey
19: 20272 434456 [Ljava.lang.Class;
20: 17270 414480 java.beans.MethodRef
21: 23616 377856 java.lang.Integer
22: 11192 358144 java.util.LinkedList
23: 14911 357864 java.util.ArrayList
24: 5700 319200 java.beans.MethodDescriptor
以上示例的排序是按照佔用記憶體位元組數倒序的。class name列中”[C，[B,[I “是代表char,byte,int.”[L+類名”代表其他例項。這種寫法跟Class檔案的Java的型別表述含義是一致的。
在進行問題排查時，可以使用jmap把程序記憶體使用情況dump到檔案中，或者dump**.hprof**檔案,在本地使用MAT(Eclipse Memory Analyzer)進行分析。也可以直接用jhat分析檢視。
/opt/app# jmap -dump:format=b,file=heapdump 6
Dumping heap to /opt/app/logs/heapdump ...
Heap dump file created
/opt/app# jmap -dump:live,format=b,file=heapLive.hprof 6 jstack [option] pid
jstack可以用來檢視Java程序內的執行緒堆疊資訊。
-l long listings，會打印出額外的鎖資訊，在發生死鎖時可以用jstack -l pid來觀察鎖持有情況
-m mixed mode，不僅會輸出Java堆疊資訊，還會輸出C/C++堆疊資訊（比如Native方法）
輸出資訊如下：
/opt/app # jstack -l 6
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.121-b13 mixed mode):
"elasticsearch[Oneg the Prober][listener][T#1]" #221 daemon prio=5 os_prio=0 tid=0x00007fc2a418a800 nid=0x195 waiting on condition [0x00007fc28318d000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000e29f88d0> (a java.util.concurrent.LinkedTransferQueue)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.LinkedTransferQueue.awaitMatch(LinkedTransferQueue.java:737)
at java.util.concurrent.LinkedTransferQueue.xfer(LinkedTransferQueue.java:647)
at java.util.concurrent.LinkedTransferQueue.take(LinkedTransferQueue.java:1269)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- None
在線上問題排查執行緒鎖資訊時，jstack是個非常好用的工具，結合應用日誌可以迅速定位到問題執行緒。
Java效能分析工具
對於Java效能調優，以前一直比較好用的工具是JRockit,JProfile(商業)等工具，但隨著JDK7 up40版本之後，jdk會自帶JMC(JavaMissionControl)工具。可以分析本地應用以及連線遠端ip使用。提供了實時分析執行緒、記憶體，CPU、GC等資訊的視覺化介面。從jdk8 up40開始，JMC還提供了在執行時建立JFR記錄(飛行記錄器)。如果是全面分析heap dump,再綜合使用MAT(Eclipse Memory Analyzer)。基本就可以做很多日常的效能調優以及線上問題排查了。下文簡單介紹一些JMC,基於java version “1.8.0_60”。
Java Mission Control
在Mac上使用的話，需要先找到jdk中的jmc路徑。
$find /Library/Java -name missioncontrol
在我本地的目錄是/Library/Java/JavaVirtualMachines/jdk1.8.0_60.jdk/Contents/Home/lib/missioncontrol/。開啟jmc之後，常用的話可以留在dock下面。
啟動需要觀察的應用，然後即可在JMC的MBean伺服器中觀察到綜合資訊如下：
進一步觀察記憶體以及GC的情況，檢視如下，可以觀察到執行時記憶體各個分割槽的佔用率。對於“堆直方圖”預設是不開啟的，可以通過右上角的重新整理值來啟用，會影響效能。一般用於排查記憶體中的大物件的回收問題以及OOM問題時可以開啟觀察。
對於執行緒死鎖、執行緒池資源方面的分析，可以到執行緒檢視中觀察活動執行緒。
Java飛行記錄器（Java Flight Recorder）
Java 8 up40開始，可以使用JMC建立JFR記錄。JFR可以取樣分析收集Java應用程式以及JVM的資訊, 它的最小開銷小於2%,不會影響其他JVM優化。JFR不會記錄所有方法呼叫，只會探測熱點方法，但不包含Native方法的執行緒取樣。如果要開啟JFR,需要應用啟動引數中新增：
-XX:+UnlockCommertialFeatures -XX:+FlightRecorder 一般還是建議本地調優和分析時使用。JFR可以提供固定時間的取樣（預設是1min），以及持續時間的記錄。它們都會dump到一個“.jfr”的檔案中。
分析記憶體資訊如下,可以看到記憶體使用量，以及基礎的GC配置和統計資訊：
詳細分析記憶體情況時，需要進一步檢視“記憶體分配”以及“物件統計資訊”。其中“物件統計資訊”也是預設不開啟的，需要在建立jfr時選擇“啟用”如下：
然後即可看到物件統計資訊：
對於熱點方法以及熱點執行緒的取樣分析圖表也很直觀，在分析一些迴圈呼叫時可以重點關注熱點方法，對於有問題的熱點方法可以進一步檢視“堆疊跟蹤”下的呼叫鏈：
總結
本文主要介紹了java常用的效能優化和排查問題的工具，以及JavaMissionControl工具的一些功能。JMC是官方提供的免費工具，結合MAT，基本可以處理效能優化的80%場景。JMC還可以連結遠端ip進行分析。但對於線上問題排查，還是建議使用jstat,jstack，jmap工具等，結合top、vmstat等快速排查和定位問題。
效能排查一般問題都集中在cpu、記憶體。前者分析執行緒，後者分析具體出現問題的記憶體分割槽。對於磁碟、IO等資源瓶頸需要綜合很多業務場景進行具體定位。
還有一部分比較大的話題，就是GC，會在下一篇進行總結和整理。