Java虛擬機器效能監控與調優實戰
監控的指標和工具
jps:虛擬機器程序狀況工具利用jps工具可以顯示當前虛擬機器中執行的java程序,並且jps後面可以跟引數,-l是輸出主類名,-v可以輸出JVM啟動時候的引數配置。寫了如下一段java程式碼做了個測試。
package com.ctgu.chenjun;
public class TraditionalThread {
public static void main(String[] args) {
Thread thread = new Thread() {
public void run() {
while(true){
try{
Thread.sleep(1000);
}catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("1:"+Thread.currentThread().getName()); }
}
};
thread.start();
Thread thread2 = new Thread(new Runnable() {
@Override
public void run() {
while(true){
try{
Thread.sleep(1000);
}catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("2:"+Thread.currentThread().getName());
}
}
});
thread2.start();
new Thread(new Runnable() {
@Override
public void run() {
while(true){
try{
Thread.sleep(1000);
}catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("Runnable"+Thread.currentThread().getName());
}
}
}){
public void run() {
while(true){
try{
Thread.sleep(1000);
}catch (InterruptedException e) {
e.printStackTrace();
}
System.out.println("3:"+Thread.currentThread().getName());
}
}
}.start();
}
}
圖3.1 jsp監控java執行程序
圖3.2 jsp輸出JVM啟動時引數
如圖3.1所示有個TraditionalThread程序在執行,顯示主類的全名,程序號為3396,jps工具本身也是一個java程式,程序號為5424,程序號3584就是main函式所在的程序了。一共有3個程序在執行。如圖3.2所示,jsp –v輸出了JVM啟動載入jdk裡面內建的tools.jar等等,JVM的引數配置,堆記憶體最小為40M,堆記憶體最大為512M,永久代最大為256M。
jstat:虛擬機器執行時資訊監控jstat是用來監控JVM執行時的狀態資訊的工具,可以檢視JVM中類的裝載、堆記憶體的詳細資訊、垃圾收集等等。我們編寫如下測試程式碼,
package com.ctgu.chenjun;
import java.util.ArrayList;
import java.util.List;
public class HeapOOM {
staticclass OOMObject {
}
publicstatic void main(String[] args) {
List<OOMObject>list = new ArrayList<OOMObject>();
while(true){
list.add(newOOMObject());
}
}
}
圖3.3 JVM執行時類裝載
圖3.4 JMV執行時堆記憶體資訊
如圖3.3所示,Loaded表示載入了15944個類,Bytes表示載入類的合計大小,Unloaded表示解除安裝類數量為50個,第2個Bytes表示解除安裝類的大小,Time表示在載入類和解除安裝類上所花費的時間。如圖3.4所示,S0C表示是s0的大小為6144位元組,S0C表示是s1的大小為6144位元組,S0U表示是s0區已使用大小為0,S1U表示是s1區已使用大小為0,Eden大小為49728位元組,Eden:S1 :S0 = 8:1:1,滿足之前的分代記憶體模型。EU表示Eden已使用4463.3位元組,OC表示老年代大小為123908個位元組,OU表示老年代已使用55962.2位元組。PC表示永久代大小為61952位元組,PU表示已使用61746.6位元組。YGC表示新生代發生GC的次數為25次,YGCT表示新生代GC的耗時為0.504秒,FGC表示Full GC的次數為60次,FGCT耗時為17.268秒,GCT表示GC的總耗時為17.772秒。
圖3.5 顯示堆記憶體各區域使用百分比
如圖3.5所示s0區域使用百分比為0,s1區域使用百分比為0,Eden區域使用大小2.45%,老年代區域使用大小為46.42%,永久代區域使用大小為99.88%。說明永久代已經溢位了。
jmap:匯出堆檔案分析我們繼續用3.1.2中程式碼做測試,並且通過設定引數-Xms20m -Xmx20m設定堆記憶體大小為20M,通過設定引數-XX:+HeapDumpOnOutOfMemoryError讓虛擬機器在發生記憶體溢位時將當前的堆記憶體轉存為快照,方面後面對堆記憶體做分析,甚至可以找出堆記憶體洩露的原因。還需要用到一款記憶體分析工具MAT(Memory Analyzer Tool),是一個功能強大、視覺化的Java heap記憶體分析工具,它可以幫助我們分析Java堆記憶體洩漏和記憶體消耗的情況。使用MAT記憶體分析工具對堆記憶體的使用情況進行分析,堆記憶體中各個物件的佔用記憶體大小及各個物件的數量一清二楚的,看看是哪個存活的物件阻止了垃圾收集器的回收工作,並可以通過報表直觀的檢視到可能造成記憶體洩露的物件,從而再去找出記憶體洩露的程式碼。
圖3.6 MAT分析堆快照
如圖3.6所示利用MAT工具對堆記憶體的快照進行分析,堆記憶體剩餘空間為369.5kb,說明堆記憶體空間不足;如圖3.7所示,圖片表明這個OOMObject類的例項最多,達到了1215488個,那麼很明顯這個資料是有異常的,程式怎麼會呼叫一個類的這麼多例項呢。接下來對這個類進一步觀察和分析,如圖3.8所示,有這麼多個Object類的例項,接著去程式碼中排查,找到可能出現Object類的區域性程式碼,那就是List<OOMObject> list= new ArrayList<OOMObject>()一直死迴圈;因為OOMObject的例項物件放入ArrayList中會被轉成Object資料型別。通過MAT堆記憶體分析工具找到了記憶體洩露的原因了,然後對區域性程式碼做修改,避免記憶體洩露。
圖3.7 MAT分析進一步分析堆快照
圖3.8 定位到有異常的類
JVM垃圾回收對效能的影響Java虛擬機器中的垃圾回收器就是為了識別和回收垃圾物件,從而實現自動回收記憶體。為了讓垃圾收集器正常並且高效的工作,在垃圾回收器工作時候系統會進入一個停頓的狀態。系統停頓的目的是終止所有執行緒的執行,這樣系統中就不會有新垃圾產生,垃圾回收器也可以更好的標記垃圾回收物件。在垃圾回收時,應用程式都會發生短暫的停頓,停頓現象發生時,整個應用程式都沒有響應,應用程式會卡死。這個停頓現象也稱為“Stop-The-World”。我們編寫如下測試程式碼,
package com.ctgu.chenjun;
import java.util.HashMap;
public class StopWorldTest {
publicstatic class MyThread extends Thread{
HashMapmap = new HashMap();
publicvoid run() {
try{
while(true){
if(map.size()*512/1024/1024>= 900) {
map.clear();
System.out.println("cleanmap");
}
byte[]b1;
for(inti = 0; i < 100; i++) {
b1= new byte[512];
map.put(System.nanoTime(),b1);
}
Thread.sleep(1);
}
}catch (Exception e) {
}
}
}
publicstatic class PrintThread extends Thread {
publicstatic final long starttime = System.currentTimeMillis();
publicvoid run() {
try{
while(true){
longt = System.currentTimeMillis() - starttime;
System.out.println(t/1000+"."+t%1000);
Thread.sleep(100);
}
}catch (Exception e) {
}
}
}
publicstatic void main(String args[]) {
MyThreadt = new MyThread();
PrintThreadp = new PrintThread();
t.start();
p.start();
}
}
在上面程式碼中開啟了兩個執行緒,PrintThread執行緒是每0.1秒在控制檯上進行一次時間戳的輸出,MyThread則不停地消耗堆記憶體資源,從而引發GC的執行。並且設定了一個臨界值,當記憶體消耗大於900M時,清空記憶體,防止堆記憶體溢位。
並且通過引數指定虛擬機器堆記憶體大小為1G,新生代大小為512k,指定使用Serial垃圾回收器,並且輸出GC日誌。程式執行的部分結果如圖3.9所示,
圖3.9 程式執行的部分結果
大約是每隔0.1秒就會有次輸出,但是從28.572秒到30.173秒有著1.601秒的時間間隔。
28.925:[GC28.925: [DefNew: 448K->448K(448K), 0.0000472 secs]28.925: [Tenured:1047926K->1040159K(1048064K), 1.5213508 secs]1048374K->1040159K(1048512K), [Perm : 1655K->1655K(12288K)], 1.5216409secs] [Times: user=1.51 sys=0.00, real=1.52 secs]
在程式列印的28.925秒處發生了1.52秒的停頓,這就能說明GC對執行程式的影響。
JVM的棧溢位其中Java堆和虛擬機器棧是比較容易出現溢位的現象,這部分實驗是用來演示Java虛擬機器棧出現溢位的現象,實驗中我們防止虛擬機器自己擴充套件Java虛擬機器棧的大小,通過設定引數Xss=128k來控制Java虛擬機器棧所允許的最大深度,本次實驗我們設定為128K大小。我們編寫如下測試程式碼:
publicclass JavaVMStackSOF {
private int stackLength = 1;
public void stackLeak() {
stackLength++;
stackLeak();
}
public static void main(String[] args) throwsThrowable {
JavaVMStackSOF oom = newJavaVMStackSOF();
try {
oom.stackLeak();
} catch (Throwable e) {
System.out.println("stacklength:"+ oom.stackLength);
throw e;
}
}
}
圖3.10 測試Java虛擬機器棧
如圖3.10所示,報Java虛擬機器棧溢位錯誤。在Xss為128K大小。同時代碼中也輸出了執行緒請求的棧深度最大為2401。
調優案例 實驗環境及案例實驗平臺基於的作業系統是windowsserver 2008,JDK是1.7版本,tomcat是7.0版本。硬體的推薦配置如表4-1所示:
表4-1 系統硬體配置
名稱 | 規格和數量 |
CPU | AMD10 4核 |
記憶體 | 8G DDR3 記憶體 |
本實驗中調優所用案例是一個Javaweb的網站如圖4.1所示,網站所採用的主要技術是Spring加上Hibernate框架,資料庫採用的是主流的Mysql資料庫。實驗原理:選擇不同的垃圾回收器和堆大小對Java應用程式的效能有一定的影響;本實驗將配置不同的虛擬機器引數啟動Tomcat伺服器,通過壓力測試,獲得虛擬機器的主要效能指標,體驗不同的引數對系統性能的影響。通過JMeter對Tomcat增加壓力測試,設定不同的虛擬機器引數Tomcat伺服器將會有不同的效能表現,Tomcat的效能表現就體現在網站的吞吐量,通過觀察不同引數配置對吞吐量的影響。系統結構如圖4.2所示為防止JMeter對Tomcat產生影響,測試時使用兩臺獨立的計算機,通過區域網相連。文中第三節對JVM監控採用的工具都是JDK自帶的控制檯工具,隨著JVM發展及重要性的凸顯,第三方的視覺化監控工具出現了,在本實驗中採用視覺化的VisualVM工具來監控JVM,方便資料的檢視和做實驗分析。
圖4.1 案例網站的首頁
圖4.2 系統結構圖
實驗工具使用圖4.3和圖4.4是採用Visual VM監控工具得到的,如圖4.3所示我們可以看到CPU使用1%不到,堆的大小,已裝載類的總數量為7546,如圖4.4所示我們會發現,總共GC次數是214次,共耗時2.751秒,其中MinorGC 201次,耗時1.325秒,Full GC 13次,耗時1.426秒,這就說明我們堆記憶體不夠大,導致GC頻繁發生。
圖 4.3 Tomcat執行時情況
圖 4.4 Tomcat執行時JVM堆記憶體及GC的情況
Jmeter軟體是Apache組織開發的,是對Java程式語言做的壓力測試工具,在本實驗中將採用Jmeter來對web網站做壓力測試,通過Jmeter提供的聚合報告來檢視網站的吞吐量,最終的目的是讓網站吞吐量達到最大。壓力測試的執行緒組是固定的,為了做對比分析,如圖4.3所示,開啟了10個執行緒,在一秒內啟動,每個執行緒訪問500次,總的訪問量就是5000.伺服器IP、埠及資源路徑配置如圖4.6所示,前提是網站攔截器要登出掉,因為這樣不用登陸就可以訪問網站首頁資源了。然後通過聚合報告得到網站吞吐量的資料。
圖 4.5 壓力測試的執行緒組
圖4.6 http請求配置
網站吞吐量測試及提高 通過增大Java堆容量提升網站吞吐量通過在Tomcat中catalina.bat檔案中設定虛擬機器引數,剛開始設定JVM堆大小為32M,setJAVA_OPTS=”-Xloggc:gc.log-XX:+PrintGCDetails –Xmx32M–Xms32M”,如下圖4.7所示,直接堆記憶體溢位,說明設定堆記憶體過小。
圖 4.7 堆記憶體溢位
於是將堆記憶體改為64M,set JAVA_OPTS=”-Xloggc:gc.log-XX:+PrintGCDetails -Xmx64M -Xms64M”,可以正常執行,並通過Jmeter來進行壓力測試,通過聚合報告來看網站吞吐量,VisualVM觀察堆的記憶體使用的情況來優化網站吞吐量。圖4.8是聚合報告,吞吐量是462.1/s.圖4.9分別是堆記憶體GC的情況。如圖所示GC所用時間為1.036秒,其中Minor GC 71次,用時613.172毫秒,Full GC 4次用時423.062毫秒,說明給的堆記憶體大小還比較合適,因為Full GC的次數較少。但是Minor GC次數有點多,說明年輕代空間偏小。
圖 4.8 堆為64M的聚合報告
圖 4.9 堆為64M的GC情況
於是將堆記憶體改為128M,set JAVA_OPTS=”-Xloggc:gc.log-XX:+PrintGCDetails –Xmx128M–Xms128M”, 可以正常執行,並通過Jmeter來進行壓力測試,通過聚合報告來看網站吞吐量,VisualVM觀察堆的記憶體使用的情況來優化網站吞吐量。圖4.10是聚合報告,吞吐量是921.5/s.圖4.11分別是堆記憶體GC的情況。如圖所示GC總次數為37次,所用時間為690.028毫秒,其中Minor GC35次,用時226.35毫秒,Full GC 2次用時240.984毫秒,這就說明給的堆記憶體大小還比較大,因為Full GC的次數很少。Minor GC次數正常,其中垃圾回收佔用時長很小,所以堆記憶體為128M比64M的吞吐量高很多。
圖 4.10 堆為128M的聚合報告
圖 4.11 堆為128M的GC情況
通過指定垃圾收集器來提升網站的吞吐量垃圾收集器為CMS,堆記憶體大小為64M,set JAVA_OPTS=”-Xloggc:gc.log -XX:+PrintGCDetails-Xmx64M -Xms64M -XX:+UseConcMarkSweepGC”。 並通過Jmeter來進行壓力測試,通過聚合報告來看網站吞吐量,VisualVM觀察堆的記憶體使用的情況來優化網站吞吐量。圖4.12是聚合報告,吞吐量是1035.6/s。圖4.13分別是堆記憶體GC的情況。如圖所示GC所用時間為868.786毫秒,其中Minor GC 71次,用時472.29毫秒,Full GC 21次用時396.496毫秒。那是因為CMS收集器優點就是:併發收集、低停頓。是一種以獲取最短回收停頓時間為目標的收集器,很適合B/S系統的服務端,希望系統停頓短暫,給使用者較好的體驗。但是還是有缺點,缺點是對CPU資源敏感,當CPU資源不是很充足時,反而會降低吞吐量。
圖 4.12 堆為64M、CMS垃圾收集器的聚合報告
圖 4.13 堆為64M、CMS垃圾收集器的GC情況
另外一個缺點是CMS會產生大量空間碎片,因為CMS是基於標記-清除演算法實現的垃圾收集器,所以Full GC的次數會到達21次。
垃圾收集器為G1,堆記憶體大小為64M不變,set JAVA_OPTS=”-Xloggc:gc.log -XX:+PrintGCDetails-Xmx64M -Xms64M -XX:+UseG1GC”。並通過Jmeter來進行壓力測試,通過聚合報告來看網站吞吐量,VisualVM觀察堆的記憶體使用的情況來優化網站吞吐量。圖4.14是聚合報告,吞吐量是655.6/s。圖4.15分別是堆記憶體GC的情況。如圖所示GC所用時間為1.584秒,其中Minor GC102次,用時1.584秒,Full GC 0次用時0。G1垃圾收集器是最前沿的成果,有併發收集、分代收集、整理碎片功能,所以Full GC次數為0,但是G1是應用到整個堆上,雖然有分代的概念,但是老年代和年輕代不再是物理隔離的,而是一塊不連續的區域,G1會在後臺維護一個優先列表,根據回收的空間和時間來確定回收哪一塊空間。這樣來說對於新生代老說不是太好,因為新生代空間小,本來會頻繁發生GC,所以對整體吞吐量提升不是太高,期待JDK團隊研究出更高階版本的G1。
圖4.14 堆為64M、G1垃圾收集器的聚合報告
圖4.15 堆為64M、G1垃圾收集器的GC情況
根據垃圾收集器種類和堆記憶體大小來做整體的優化堆記憶體大小設為1024M,垃圾收集器用CMS,永久區大小設為512M,set JAVA_OPTS=”-Xloggc:gc.log-XX:+PrintGCDetails -Xmx1024M -Xms1024M -XX:+UseConcMarkSweepGC-XX:PermSize=512M”。 並通過Jmeter來進行壓力測試,通過聚合報告來看網站吞吐量,VisualVM觀察堆的記憶體使用的情況來優化網站吞吐量。圖4.16是聚合報告,吞吐量是1455.2/s。圖4.17分別是堆記憶體GC的情況。如圖所示GC所用時間為311.244毫秒,其中Minor GC6次,用時311.244毫秒,Full GC 0次用時0。這次實驗中,同時增加了永久區的大小,是因為從之前的日誌裡發現永久代也觸發了GC,雖然次數很少。和前面實驗對比,這次實驗的吞吐量最高,吞吐量也提升了很多。
圖4.16 堆為1024M、垃圾收集器為CMS、永久區為512M的聚合報告
圖4.17 堆為1024M、垃圾收集器為CMS、永久區為512M的GC情況