1. 程式人生 > >Java應用執行非常慢,如何分析

Java應用執行非常慢,如何分析

##   機器應用配置

1. 生產環境批量總共4臺機器,地址分別為10,11,12,13,
1. 機器配置均為至強96邏輯CPU,252G記憶體,萬兆網絡卡
1. 每臺機器部署6個批量應用伺服器,總共25*6*4=600併發
1. 作業配置為4G記憶體年輕代1536M

##    問題現象:

1. 應用一週左右未重啟會出現執行批量特別慢的情況,平時600w資料跑完半小時左右,出問題的應用可能要2個小時甚至更長,重啟可以恢復正常,不重啟第二天可能還會慢,也有可能會恢復。
1. 出問題的機器,應用,交易不固定,同一臺機器某個或某幾個應用出問題其他應用正常執行不受任何影響,出問題的應用所有交易執行時間拉長,所有的操作都會變慢,但是能正常跑完。


## 問題分析

1. 之前懷疑是網路,I/O問題,現在基本可以排除,因為觀察網路和磁碟io佔用很小
1. 懷疑是由於記憶體佔用太高導致的,然後機器記憶體剩餘80G左右,應用記憶體佔用均正常。機器CPU佔用70%以下

1. 分析heapdump和gc,jstack日誌沒有發現明顯的異常,應用也沒有任何報錯,無解。

1. 對出問題的應用使用jmap -histo:live [pid]命令,應用會恢復正常,目前測試了出問題的幾個應用,都有效果,但是目前還不清楚原因。

1. 應用FullGc非常少,一天能有一次就不錯了。younggc也還好,高頻的時候也就30s左右一次,每次29ms這樣。

1. 懷疑記憶體洩露,但是從dump來看並沒有什麼異常,出問題的應用堆疊基本都在執行資料庫操作,就是慢,而且出問題的應用CPU佔用比較高達到90%以上。

生產環境,不好測試,問題也不好重現,引數也不能亂改,很迷茫,不知道改怎麼解決,有沒有什麼好的方法或者思路的。。。

gc引數

-server -Xms4096m -Xmx4096m -XX:PermSize=1024M -XX:MaxPermSize=2048m  -Deos.log.home=logs -XX:+UseFastAccessorMethods 
-XX:+UseCompressedOops -XX:+DisableExplicitGC -XX:+ExplicitGCInvokesConcurrent -XX:ParallelGCThreads=10 
-XX:-UseAdaptiveSizePolicy -Xmn1536m -XX:SurvivorRatio=6 -XX:+UseParallelGC -XX:+UseParallelOldGC
 -XX:MaxTenuringThreshold=20 -XX:MaxGCPauseMillis=200 -XX:+PrintAdaptiveSizePolicy -XX:+PrintGCApplicationStoppedTime
 -XX:+PrintGCApplicationConcurrentTime -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:-TraceClassUnloading 
-XX:+PrintGCDetails -Xloggc:gc.log 

分析工具:jmap,jstack,jstat , nmon,nmon分析工具,top,MemoryAnalyzer,具體用法和日誌檔案分析自行百度

JVM記憶體結構的知識,堆記憶體(年輕代,survival區,老年代),非堆記憶體(方法區,CodeCache,直接記憶體)

出問題的時候,抓javacore(jstack),檢視記憶體狀態(jstat),匯出堆記憶體快照heapdump(jmap),nmon抓日誌,top檢視狀態

主要用於:分析執行緒死鎖,程式碼問題,記憶體洩露,資源瓶頸,這些是最常見的問題,也是最先要考慮的。

---------------------------------分割線-------------------------------------------

新發現,控制檯有如下警告資訊:

Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled.
Java HotSpot(TM) 64-Bit Server VM warning: Try increasing the code cache size using -XX:ReservedCodeCacheSize=

查閱資料:

隨著時間推移,會有越來越多的方法被編譯,codeCache使用量會逐漸增加,直至耗盡。在codeCache滿了之後會發生什麼?

在jdk1.7.0_4之前,你會在jvm的日誌裡看到這樣的輸出:

Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled.

Jit編譯器被停止了,並且不會被重新啟動。已經被編譯過的程式碼仍然以編譯方式執行,但是尚未被編譯的程式碼就只能以解釋方式執行了。

針對這種情況,jvm提供了一種比較激進的codeCache回收方式:Speculative flushing。在jdk1.7.0_4之後這種回收方式預設開啟,而之前的版本需要通過一個啟動引數來開啟:-XX:+UseCodeCacheFlushing。在Speculative flushing開啟的情況下,當codeCache將要耗盡時,最早被編譯的一半方法將會被放到一個old列表中等待回收。在一定時間間隔內,如果方法沒有被呼叫,這個方法就會被從codeCache充清除。

很不幸的是,在jdk1.7中,當codeCache耗盡時,Speculative flushing釋放了一部分空間,但是從編譯日誌來看,jit編譯並沒有恢復正常,並且系統整體效能下降很多,出現大量超時。在oracle官網上看到這樣一個bug:http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8006952 由於codeCache回收演算法的問題,當codeCache滿了之後會導致編譯執行緒無法繼續,並且消耗大量cpu導致系統執行變慢。Bug裡影響版本是jdk8,但是從網上其他地方的資訊看,jdk7應該也存在相同的問題,並且沒有被修復。

做了測試結果,一致,確實會導致效能下降。

檢視預設大小:

jinfo -flag XX:ReservedCodeCacheSize 程序號

預設是48M

可以通過-XX:ReservedCodeCacheSize=256M調整大小,可以避開這個問題。

》》》》》》》》》》》》》》》》》》》》》》》》》

那麼問題來了,為什麼會滿呢,到底是什麼程式碼導致的?

增加 -XX:+PrintCompilation  -XX:+CITime 列印JIT編譯資訊,沒什麼發現,原始資料太難看了,放棄。

---------------------------------------------必須有更好的工具,最好能直接觀察分析---------------------------------------------------------

jconsole可以觀察到CodeCache區,但是也只是可以看大小和監控增長情況,不能看內容。

            

JITWatch感覺很牛的樣子,github上下載了程式碼,只需maven編譯一下(mvn clean install)然後開啟./launchUI.bat就可以用了,要想檢視jit編譯的程式碼必須要hsdis才行,查了下oracle並沒有提供,沒辦法下了openjdk的Hotspot程式碼,編譯了一個,一樣好使,哈哈哈日誌打出來了,裡面也有彙編程式碼。

,這裡搬運一下:

編譯hsdis:

1.去openjdk官網下載對應的jdk版本的hostspot原始碼
2.解壓原始碼,找到src/share/tools/hsdis 資料夾
3.檢視對應的README,找到對應的binutils版本
4.去官網下載binutils對應版本
5.放到hsdis資料夾下hsdis/build/binutils目錄
6.在hsdis資料夾執行make,即可hsdis/build/linux-amd64下會生成hsdis-amd64.so
7.將hsdis-amd64.so放到JVM的libpath裡面即可,Linux下為LD_LIBPATH變數指定的位置
8.指定jvm引數-XX:+UnlockDiagnosticVMOptions -XX:+TraceClassLoading -XX:+LogCompilation -XX:+PrintAssembly

9.生成的對應hotspot_pid.log檔案裡就會列印彙編程式碼和編譯資訊!

這裡有個坑,我下的版本原始碼的makefile是有錯誤的,不過我在GitHub上找了個大神弄的,同樣可以編譯出來,然後把makefile替換掉也可以了。

附錄:
openjdk hotspot原始碼下載(我這裡下的是jdk7的,根據需要)

jitwatch地址:

----------------------------------------------------------------2018年5月22日23:49:55---------------------------------------------------------------------

接下來如何分析呢?

//TO BE CONTINUED

哈哈哈,最後啥也沒分析出來,可能還是本身平臺的問題,用的cglib代理比較多,動態生成類佔用jit太多?

總之把預設CodeCache改成256m了,目前沒有再出現問題。