天天看點

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=
           

查閱資料:

java codeCache

https://blogs.oracle.com/poonam/why-do-i-get-message-codecache-is-full-compiler-has-been-disabled

随着時間推移,會有越來越多的方法被編譯,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區,但是也隻是可以看大小和監控增長情況,不能看内容。

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

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的,根據需要)

http://hg.openjdk.java.net/jdk7u/jdk7u/hotspot/tags

jitwatch位址:

https://github.com/AdoptOpenJDK/jitwatch

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

接下來如何分析呢?

//TO BE CONTINUED

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

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