實用 JVM 引數總結
摘要: HotSpot JVM 有許多可用的引數選項,在這裡我總結了一些實用的JVM引數,包括堆大小調整、監控、JIT優化等部分
HotSpot JVM 有許多可用的引數選項,也許太多了,有時候我們會將一些正在尋找的或者“魔法式”的選項新增在我們的應用上,導致非常可怕的後果。我認為這種情況不應該存在,應該有一些選項能幫助我們監控應用或者調整應用的某些部分。
為了獲得完整的JVM引數列表,我們不僅可以參考OpenJDK原始碼裡的globals.hpp檔案,也可以從這個網站上找到這些列表。
在這裡我總結了一些實用的JVM引數,接下來我們一起學習一下。
堆大小(Heap sizing)
雖然我們已經完全理解-Xms -Xms選項(有時也被縮寫成-ms、-mx),但是Java堆和非堆中的其它一些部分也應該被設定:
- -XX:NewSize=n 定義了年輕代(Young generation)的初始大小,包括Eden(伊甸園區)和Survivors(倖存者區)
- -XX:MaxNewSize=n 定義了年輕代的最大大小,包括Eden(伊甸園區)和Survivors(倖存者區)
- -XX:SurvivorRatio=n 定義了Eden(伊甸園區)和2個倖存者區(2 survivors)之間的大小比例。
n沒有設定單位的話,預設用位元組來表示。我們也可以使用k,K, m, M, g & G來表示千位元組(kilobytes,即k、K)、兆位元組(megabytes,即m、M)和千兆位元組(gigabytes,即g、G)。
如果NewSize < MaxNewSize,年輕代(Young generation)會在應用執行期間自動地調節大小。然而年輕代的這個動態調整可能會引發Full GC,因此為了避免這個問題的發生,我們通常將這兩個引數的值設定成一樣的。
- -XX:PermSize=n 表示持久代的初始大小
- -XX:MaxPermSize=n 表示持久代的最大大小。
n沒有設定單位的話,預設用位元組來表示。我們也可以使用k,K, m, M, g & G來表示千位元組(kilobytes,即k、K)、兆位元組(megabytes,即m、M)和千兆位元組(gigabytes,即g、G)。
如果PermSize < MaxPermSize,年輕代(Young generation)會在應用執行過程中自動地調節大小。然而持久代的這個動態調整可能會引發Full GC,因此為了避免這個問題的發生,我們通常將這兩個引數的值設定成一樣的。
- -XX:InitialCodeCacheSize=n 定義了程式碼快取區的初始大小
- -XX:ReservedCodeCacheSize=n 定義了程式碼快取區的最大大小。
n沒有設定單位的話,預設用位元組來表示。我們也可以使用k,K, m, M, g & G來表示千位元組(kilobytes,即k、K)、兆位元組(megabytes,即m、M)和千兆位元組(gigabytes,即g、G)。
程式碼快取區儲存著經過JIT編譯過的程式碼,這是一個堆外空間,因此GC不能回收利用它。如果達到了程式碼快取區的ReservedCodeCacheSize大小限制,由於沒有額外的空間儲存它們,JIT編譯器(JIT Compiler)將停止編譯更多的方法。因此如果我們有很多類和方法需要被編譯的話,注意這個選項的設定。
當達到最大限制時,JVM會輸出如下警告:
Java HotSpot(TM) Server VM warning: CodeCache is full. Compiler has been disabled
用-XX:+PrintCompilation引數我們可以看到:
7383 COMPILE SKIPPED: code cache is full
GC 設定/調整(GC Settings/Tuning)
配置GC,有大量的選項,比如對於CMS來說,最後幾個非常有用。在這裡我不會來微調CMS。
- -XX:+UseSerialGC 表示啟用單執行緒方式來進行年輕代GC(young GC)
- -XX:+UseParallelGC 表示啟用多執行緒方式來進行年輕代GC(young GC)
- -XX:+UseParallelGC 表示啟用另一種多執行緒方式來進行年輕代GC(young GC),但是需要和CMS垃圾收集器一起使用
- -XX:+UseParalelOldGC 表示啟用多執行緒方式來進行老年代GC(Old GC)
- -XX:+UseConcMarkSweepGC 表示啟用並行GC(Concurrent GC)
- -XX:+UseG1GC 表示啟用G1 GC(Garbage First GC)
- -XX:ParallelGCThreads=n 設定進行並行GC(Parallel*GC)的執行緒數量,避免相同機器上多個JVM的GC執行緒互相干擾。
通過-XX:ParallelGCThreads=<value>我們可以指定並行垃圾收集的執行緒數量。 例如,-XX:ParallelGCThreads=6表示每次並行垃圾收集將有6個執行緒執行。 如果不明確設定該標誌,虛擬機器將使用基於可用(虛擬)處理器數量計算的預設值。 決定因素是由Java Runtime物件的availableProcessors()方法的返回值N,如果N<=8,並行垃圾收集器將使用N個垃圾收集執行緒,如果N>8個可用處理器,垃圾收集執行緒數量應為3+5N/8。
當JVM獨佔地使用系統和處理器時使用預設設定更有意義。 但是,如果有多個JVM(或其他耗CPU的系統)在同一臺機器上執行,我們應該使用-XX:ParallelGCThreads來減少垃圾收集執行緒數到一個適當的值。 例如,如果4個以伺服器方式執行的JVM同時跑在一個具有16核處理器的機器上,設定-XX:ParallelGCThreads=4是明智的,它能使不同JVM的垃圾收集器不會相互干擾。(引自JVM實用引數-6 吞吐量收集器關於該引數的解釋部分)
- -XX:CMSInitiatingOccupancyFraction=n 設定CMS垃圾收集器開始GC時,老年代所佔JVM大小的比例,當分配率不可預測時,這個選項是有用的
- -XX:+UseCMSInitiatingOccupancyOnly 設定JVM不基於執行時收集的資料來啟動CMS垃圾收集週期。而是,當該標誌被開啟時,JVM通過CMSInitiatingOccupancyFraction的值進行每一次CMS收集,而不僅僅是第一次。然而,請記住大多數情況下,JVM比我們自己能作出更好的垃圾收集決策。因此,只有當我們充足的理由(比如測試)並且對應用程式產生的物件的生命週期有深刻的認知時,才應該使用該標誌。(引自JVM實用引數(七)CMS收集器關於該引數解釋部分)
- -XX:+CMSClassUnloadingEnabled 相對於並行收集器,CMS收集器預設不會對永久代進行垃圾回收。如果希望對永久代進行垃圾回收,可用設定標誌-XX:+CMSClassUnloadingEnabled。在早期JVM版本中,要求設定額外的標誌-XX:+CMSPermGenSweepingEnabled。注意,即使沒有設定這個標誌,一旦永久代耗盡空間也會嘗試進行垃圾回收,但是收集不會是並行的,而再一次進行Full GC。
GC監控
對於應用程式來說,為了診斷記憶體管理的任何異常行為,絕對需要用一個單獨的日誌檔案來記錄GC活動。並且,啟用這些資訊對您的應用程式幾乎沒有影響,所以沒有理由不啟用這些選項。
-Xloggc:file 表示GC日誌檔案被寫入的路徑
通過這個選項,我們可以獲得以下日誌:
8.567: [GC 16448K->168K(62848K), 0.0014256 secs] 16.979: [GC 16616K->152K(62848K), 0.0007727 secs] 25.157: [GC 16600K->152K(62848K), 0.0007124 secs] 33.881: [GC 16600K->136K(62848K), 0.0003721 secs] 43.032: [GC 16584K->152K(59968K), 0.0004123 secs] 50.795: [GC 16216K->152K(59584K), 0.0009683 secs] 58.584: [GC 15832K->148K(59136K), 0.0008669 secs] 66.430: [GC 15508K->148K(58816K), 0.0003436 secs] 73.766: [GC 15188K->148K(58688K), 0.0002917 secs] 81.082: [GC 14868K->148K(58176K), 0.0003157 secs] 88.851: [GC 14548K->148K(58048K), 0.0003148 secs] 96.379: [GC 14228K->148K(57536K), 0.0003129 secs] 101.618: [GC 13908K->704K(57472K), 0.0032532 secs] 102.684: [GC 3206K->744K(57280K), 0.0034611 secs] 102.687: [Full GC 744K->723K(57280K), 0.0525762 secs] 109.313: [GC 14227K->755K(57344K), 0.0005165 secs] 115.905: [GC 14003K->779K(56768K), 0.0006688 secs]
-XX:+PrintGCDetails 啟用更詳細的GC日誌資訊
通過這個選項,我們可以獲得以下日誌:
9.053: [GC [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0014471 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 16.991: [GC [PSYoungGen: 16616K->152K(19136K)] 16616K->152K(62848K), 0.0008244 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 24.965: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0006850 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 32.915: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0007040 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 40.857: [GC [PSYoungGen: 16600K->152K(16256K)] 16600K->152K(59968K), 0.0007618 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 48.653: [GC [PSYoungGen: 16216K->152K(15872K)] 16216K->152K(59584K), 0.0007632 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 53.896: [GC [PSYoungGen: 15832K->192K(15552K)] 15832K->620K(59264K), 0.0131835 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 55.252: [GC [PSYoungGen: 3888K->64K(15424K)] 4317K->716K(59136K), 0.0025925 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 55.255: [Full GC (System) [PSYoungGen: 64K->0K(15424K)] [PSOldGen: 652K->715K(43712K)] 716K->715K(59136K) [PSPermGen: 5319K->5319K(16384K)], 0.0269456 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 62.544: [GC [PSYoungGen: 15360K->32K(15488K)] 16075K->747K(59200K), 0.0006252 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 69.502: [GC [PSYoungGen: 15072K->32K(14784K)] 15787K->747K(58496K), 0.0003713 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
從上面的日誌中,我們可以看到更多和有價值的資訊。我們能知道年輕代和老年代(Young & Old)被配置的GC型別(PSYoungGen & PSOlgGen = ParallelScavenge, ParallelGC),由於顯式呼叫了System.GC()而觸發了full gc,還有年輕代和老年代記憶體使用的詳細資訊,從而可以判斷出是否需要調整兩者的大小。對於CMS垃圾收集器,可以記錄CMS整個階段的初始標記暫停時間和重新標記暫停時間(Initial Mark pause time & Remark pause time)。
-XX:+PrintGCDateStamps 輸出自JVM啟動到垃圾收集發生時的日期時間戳,以及垃圾收集時間
通過這個選項,我們可以獲得以下日誌:
2012-11-08T22:31:12.310+0100: 8.250: [GC [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0007445 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:20.526+0100: 16.466: [GC [PSYoungGen: 16616K->136K(19136K)] 16616K->136K(62848K), 0.0008255 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:28.503+0100: 24.444: [GC [PSYoungGen: 16584K->152K(19136K)] 16584K->152K(62848K), 0.0007196 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 2012-11-08T22:31:36.497+0100: 32.439: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0007185 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:44.565+0100: 40.507: [GC [PSYoungGen: 16600K->152K(16256K)] 16600K->152K(59968K), 0.0007928 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:52.694+0100: 48.637: [GC [PSYoungGen: 16216K->152K(15872K)] 16216K->152K(59584K), 0.0007599 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:58.204+0100: 54.147: [GC [PSYoungGen: 15832K->192K(15552K)] 15832K->620K(59264K), 0.0072012 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 2012-11-08T22:31:59.999+0100: 55.942: [GC [PSYoungGen: 4932K->64K(15424K)] 5360K->716K(59136K), 0.0015449 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:32:00.000+0100: 55.944: [Full GC (System) [PSYoungGen: 64K->0K(15424K)] [PSOldGen: 652K->716K(43712K)] 716K->716K(59136K) [PSPermGen: 5311K->5311K(16384K)], 0.0273445 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2012-11-08T22:32:07.453+0100: 63.397: [GC [PSYoungGen: 15360K->32K(15488K)] 16076K->748K(59200K), 0.0003439 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:32:14.695+0100: 70.640: [GC [PSYoungGen: 15072K->32K(14784K)] 15788K->748K(58496K), 0.0007333 secs]
如果要去掉JVM執行時間(elapsed time)的話,我們可以使用-XX:-PrintGCTimeStamps選項,該選項預設被-Xloggc選項啟用
-XX:+PrintReferenceGC 輸出指定引用(special references)處理的時間
通過這個選項,我們可以獲得以下日誌:
8.494: [GC8.496: [SoftReference, 0 refs, 0.0000084 secs]8.496: [WeakReference, 3 refs, 0.0000061 secs]8.496: [FinalReference, 6 refs, 0.0000117 secs]8.496: [PhantomReference, 0 refs, 0.0000042 secs]8.496: [JNI Weak Reference, 0.0000034 secs] [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0017036 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 16.874: [GC16.874: [SoftReference, 0 refs, 0.0000050 secs]16.874: [WeakReference, 1 refs, 0.0000034 secs]16.874: [FinalReference, 4 refs, 0.0000036 secs]16.874: [PhantomReference, 0 refs, 0.0000028 secs]16.874: [JNI Weak Reference, 0.0000028 secs] [PSYoungGen: 16616K->152K(19136K)] 16616K->152K(62848K), 0.0005199 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 24.889: [GC24.890: [SoftReference, 0 refs, 0.0000078 secs]24.890: [WeakReference, 1 refs, 0.0000053 secs]24.890: [FinalReference, 4 refs, 0.0000056 secs]24.890: [PhantomReference, 0 refs, 0.0000039 secs]24.890: [JNI Weak Reference, 0.0000036 secs] [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0008915 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 32.829: [GC32.830: [SoftReference, 0 refs, 0.0000084 secs]32.830: [WeakReference, 1 refs, 0.0000050 secs]32.830: [FinalReference, 4 refs, 0.0000056 secs]32.830: [PhantomReference, 0 refs, 0.0000045 secs]32.830: [JNI Weak Reference, 0.0000045 secs] [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0009845 secs]
通過以上日誌,可以幫助我們排查指定引用(special references)比如Weak, Soft, Phantom & JNI所引起的問題。
-XX:+PrintTenuringDistribution 輸出在倖存者區(Survivors)物件的年齡分佈(age distribution)
通過這個選項,我們可以獲得以下日誌:
8.654: [GC 8.655: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 187568 bytes, 187568 total : 17472K->190K(19648K), 0.0022117 secs] 17472K->190K(63360K), 0.0023006 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 17.087: [GC 17.087: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 80752 bytes, 80752 total - age 2: 166752 bytes, 247504 total : 17662K->286K(19648K), 0.0036440 secs] 17662K->286K(63360K), 0.0037619 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 25.491: [GC 25.491: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 104008 bytes, 104008 total - age 2: 34256 bytes, 138264 total - age 3: 166752 bytes, 305016 total : 17758K->321K(19648K), 0.0035331 secs] 17758K->321K(63360K), 0.0036424 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 34.745: [GC 34.746: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 34400 bytes, 34400 total - age 2: 104008 bytes, 138408 total - age 3: 34256 bytes, 172664 total - age 4: 166752 bytes, 339416 total : 17793K->444K(19648K), 0.0040891 secs] 17793K->444K(63360K), 0.0042000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 43.215: [GC 43.215: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 138808 bytes, 138808 total - age 2: 34400 bytes, 173208 total - age 3: 34264 bytes, 207472 total - age 4: 34256 bytes, 241728 total - age 5: 166752 bytes, 408480 total : 17916K->586K(19648K), 0.0048752 secs] 17916K->586K(63360K), 0.0049889 secs]
上面日誌輸出了JVM在每次新生代GC(minor GC,包括Survivor spaces)後,倖存區中物件的年齡分佈。
-XX:+PrintHeapAtGC 輸出各個空間的使用情況
通過這個選項,我們可以獲得以下日誌:
{Heap before GC invocations=1 (full 0): PSYoungGen total 19136K, used 16448K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 100% used [0x33f20000,0x34f30000,0x34f30000) from space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) to space 2688K, 0% used [0x34f30000,0x34f30000,0x351d0000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1715K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561ccc8,0x06470000) 8.304: [GC [PSYoungGen: 16448K->228K(19136K)] 16448K->228K(62848K), 0.0028543 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap after GC invocations=1 (full 0): PSYoungGen total 19136K, used 228K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 0% used [0x33f20000,0x33f20000,0x34f30000) from space 2688K, 8% used [0x34f30000,0x34f69100,0x351d0000) to space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1715K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561ccc8,0x06470000) } {Heap before GC invocations=2 (full 0): PSYoungGen total 19136K, used 16676K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 100% used [0x33f20000,0x34f30000,0x34f30000) from space 2688K, 8% used [0x34f30000,0x34f69100,0x351d0000) to space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1721K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561e620,0x06470000) 16.577: [GC [PSYoungGen: 16676K->261K(19136K)] 16676K->261K(62848K), 0.0021589 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap after GC invocations=2 (full 0): PSYoungGen total 19136K, used 261K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 0% used [0x33f20000,0x33f20000,0x34f30000) from space 2688K, 9% used [0x351d0000,0x352115f0,0x35470000) to space 2688K, 0% used [0x34f30000,0x34f30000,0x351d0000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1721K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561e620,0x06470000)
我們可以看到每次minor 或者 Full GC前後,各個空間(eden, from & to survivors, old & perm)的使用情況。
-XX:+PrintSafepointStatistics 輸出安全點統計資訊
通過這個選項,當應用終止時,我們可以看到如下標準輸出:
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 4.162: EnableBiasedLocking [ 8 0 0] [0 0 0 0 0] 0 8.466: ParallelGCFailedAllocation [ 8 0 0] [0 0 0 0 2] 0 23.927: ParallelGCFailedAllocation [ 8 0 0] [0 0 0 0 2] 0 31.039: RevokeBias [ 9 0 1] [0 0 0 0 0] 0 31.377: RevokeBias [ 10 0 1] [0 0 0 0 0] 0 31.388: RevokeBias [ 11 1 1] [2 0 2 0 0] 0 31.390: ParallelGCFailedAllocation [ 11 0 0] [0 0 0 0 4] 0 31.452: RevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.487: BulkRevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.515: RevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.550: BulkRevokeBias [ 12 0 0] [0 0 0 0 0] 0 32.572: ThreadDump [ 12 0 1] [0 0 0 0 0] 0 38.572: ThreadDump [ 13 0 2] [0 0 0 0 0] 0 39.042: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 6] 0 39.575: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 39.775: ParallelGCSystemGC [ 13 0 0] [0 0 0 0 35] 0 40.574: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 45.519: HeapDumper [ 13 0 0] [0 0 0 0 93] 0 45.626: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.575: no vm operation [ 13 0 0] [0 0 0 0 0] 0 50.576: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.875: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.881: GC_HeapInspection [ 13 0 1] [0 0 0 0 9] 0 51.577: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 82.281: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 4] 0 82.578: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 88.578: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 88.999: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 4] 0 94.580: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 95.439: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 2] 0 95.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 101.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 102.276: ParallelGCFailedAllocation[ 13 0 0] [0 0 0 0 5] 0 102.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 133.776: no vm operation [ 12 0 1] [0 0 0 0 332] 0 Polling page always armed ThreadDump 103 HeapDumper 1 GC_HeapInspection 1 ParallelGCFailedAllocation 16 ParallelGCSystemGC 1 EnableBiasedLocking 1 RevokeBias 57 BulkRevokeBias 2 0 VM operations coalesced during safepoint Maximum sync time 2 ms Maximum vm operation time (except for Exit VM operation) 93 ms
這些統計輸出表示執行VM操作(vm operation)所花費的時間,也就意味著在VM操作期間所有的執行緒是停止的(比如STW GC)。
-XX:+PrintGCApplicationStoppedTime 輸出應用內所有執行緒停止的時間
通過這個選項,我們可以獲得以下日誌:
Total time for which application threads were stopped: 0.0000257 seconds 6.253: [GC [PSYoungGen: 16448K->565K(19136K)] 16448K->565K(62848K), 0.0042058 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] Total time for which application threads were stopped: 0.0045092 seconds Total time for which application threads were stopped: 0.0000916 seconds Total time for which application threads were stopped: 0.0047405 seconds Total time for which application threads were stopped: 0.0000869 seconds Total time for which application threads were stopped: 0.0000285 seconds Total time for which application threads were stopped: 0.0002229 seconds Total time for which application threads were stopped: 0.0002159 seconds 13.310: [GC [PSYoungGen: 17013K->798K(19136K)] 17013K->798K(62848K), 0.0058890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] Total time for which application threads were stopped: 0.0064142 seconds 26.148: [GC [PSYoungGen: 11951K->908K(19136K)] 11951K->908K(62848K), 0.0060538 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 26.154: [Full GC (System) [PSYoungGen: 908K->0K(19136K)] [PSOldGen: 0K->876K(43712K)] 908K->876K(62848K) [PSPermGen: 5363K->5363K(16384K)], 0.0385560 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] Total time for which application threads were stopped: 0.0450568 seconds 39.332: [GC [PSYoungGen: 16448K->150K(16256K)] 17349K->1051K(33664K), 0.0017511 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Total time for which application threads were stopped: 0.0020282 seconds
這個日誌告訴我們在VM操作(比如GC, thread dump, heap dump, revoke bias, deoptimization等)期間所有執行緒停止的實際時間。
正如你所看到的在GC過程中GC可能停止執行緒多一點,一個執行緒到達安全點(safepoint)所需的時間可能會增加開銷。
- -XX:+HeapDumpBeforeFullGC 指定在Full GC之後生成一個堆快照,這可以幫助我們排查在一個時間段Full GC發生的原因
- -XX:+PrintClassHistogramBeforeFullGC 指定在GC日誌中輸出類的直方圖(number of instances per class with bytes allocated),這是一個輕量級的堆快照
- -XX:+HeapDumpOnOutOfMemoryError 指定在記憶體溢位時(OutOfMemory)生成堆快照,這可以幫助我們判斷哪一個類或者物件導致了記憶體溢位
- -XX:HeapDumpPath=path 指定堆快照輸出的路徑(java_pid<pid>.hprof)
監控(Monitoring)
有些有用的選項可以幫助我們監視和GC無關的JVM行為。
-XX:+PrintCompilation 輸出被JIT編譯(JIT compiler)過的每個方法
通過這個選項,我們可以獲得以下標準輸出:
1 java.lang.Object::<init> (1 bytes) --- n java.lang.System::currentTimeMillis (static) 2 java.util.ArrayList::add (29 bytes) 3 java.util.ArrayList::ensureCapacity (58 bytes) --- n java.lang.Thread::sleep (static) 1% com.bempel.sandbox.TestJIT::allocate @ 7 (84 bytes) 4 com.bempel.sandbox.TestJIT::call (10 bytes) 5 java.util.ArrayList::contains (14 bytes) 6 java.util.ArrayList::indexOf (67 bytes) 4 made not entrant (2) com.bempel.sandbox.TestJIT::call (10 bytes) 7 com.bempel.sandbox.TestJIT::call (10 bytes) 8 java.util.concurrent.CopyOnWriteArrayList::contains (22 bytes) 9 java.util.concurrent.CopyOnWriteArrayList::indexOf (63 bytes) 2% com.bempel.sandbox.TestJIT::main @ 60 (83 bytes)
-XX:+LogCompilation 指定將JIT編譯資訊記錄到當前目錄下的hotspot.log檔案中,需要與-XX:+UnlockDiagnosticVMOptions選項搭配使用,以XML形式顯示這些資訊:
<task_queued compile_id='4' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <task_queued compile_id='5' method='java/util/ArrayList contains (Ljava/lang/Object;)Z' bytes='14' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <task_queued compile_id='6' method='java/util/ArrayList indexOf (Ljava/lang/Object;)I' bytes='67' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <writer thread='2508'/> <nmethod compile_id='5' compiler='C2' level='2' entry='0x024c8a00' size='788' address='0x024c8908' relocation_offset='208' code_offset='248' stub_offset='472' consts_offset='487' scopes_data_offset='496' scopes_pcs_offset='636' dependencies_offset='748' handler_table_offset='752' nul_chk_table_offset='776' oops_offset='488' method='java/util/ArrayList contains (Ljava/lang/Object;)Z' bytes='14' count='7000' backedge_count='1' iicount='12000' stamp='20.702'/> <writer thread='1392'/> <nmethod compile_id='4' compiler='C2' level='2' entry='0x024c7a40' size='776' address='0x024c7948' relocation_offset='208' code_offset='248' stub_offset='568' consts_offset='583' scopes_data_offset='604' scopes_pcs_offset='668' dependencies_offset='748' nul_chk_table_offset='756' oops_offset='584' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='7000' backedge_count='1' iicount='12000' stamp='20.703'/> <writer thread='2508'/> <nmethod compile_id='6' compiler='C2' level='2' entry='0x024c9700' size='728' address='0x024c9608' relocation_offset='208' code_offset='248' stub_offset='472' consts_offset='487' scopes_data_offset='492' scopes_pcs_offset='576' dependencies_offset='688' handler_table_offset='692' nul_chk_table_offset='716' oops_offset='488' method='java/util/ArrayList indexOf (Ljava/lang/Object;)I' bytes='67' count='7000' backedge_count='1' iicount='12000' stamp='20.707'/> <writer thread='3508'/> <uncommon_trap thread='3508' reason='class_check' action='maybe_recompile' compile_id='4' compiler='C2' level='2' stamp='21.700'> <jvms bci='3' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='7000' backedge_count='1' iicount='12000'/> </uncommon_trap>
這可以幫助我們理解為什麼有一些方法沒有被優化(deoptimized)。
- -XX:+LogVMOutput 記錄所有的VM操作輸出到當前目錄的hotspot.log檔案裡,需要和-XX:+UnlockDiagnosticVMOptions選項搭配使用
- -XX:LogFile=file 指定hotpot.log檔案的路徑和名稱,需要和-XX:+UnlockDiagnosticVMOptions選項搭配使用
- -XX:+PrintAssembly 輸出被JIT編譯器編譯後方法的分解形式,可以看我的另一篇文章,需要和-XX:+UnlockDiagnosticVMOptions選項搭配使用
- -XX:ErrorFile=file 指定JVM發生崩潰時(JVM crash),hserr<pid>.log檔案的生成路徑
- -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1234 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false 啟用JMX遠端連線,使我們可以使用VisualVM等工具遠端連線JVM
JIT Compiler
以下選項控制JIT編譯器的行為:
- -XX:CICompilerCount=n 指定JIT編譯器用來編譯方法的執行緒數量
- -XX:CompileThreshold=n 指定一個方法的呼叫次數,以使HotSpot和JIT 編譯器能編譯它
- -Xcomp 指定JVM在第一次使用時把所有的位元組碼編譯成原生程式碼. (即CompileThreshold=1)
- -Xbatch 在前臺編譯方法,直到編譯完成方法才能執行
- -Xint 僅僅使用解釋模式,不啟用JIT編譯器 (即CompileThreshold=0)
優化(Optimizations)
以下選項能啟用或者禁用特定型別的JIT優化(JIT optimizations):
- -XX:+UseCompressedStrings 指定用byte陣列(byte array)來處理String物件而不是用char陣列(char array),這雖然在一定程度上能減少堆記憶體的消耗,但是也要注意副作用(Beware of side effects),預設情況下禁用
- -XX:+UseBiasedLocking 指定啟用偏向鎖(Biased Locking),JDK1.6開始預設開啟的偏向鎖,會嘗試把鎖賦給第一個訪問它的執行緒,取消同步塊上的synchronized原語。如果始終只有一條執行緒在訪問它,就成功略過同步操作以獲得效能提升。
但一旦有第二條執行緒訪問這把鎖,JVM就要撤銷偏向鎖恢復到未鎖定執行緒的狀態,詳見 JVM的Stop The World,安全點,黑暗的地底世界, 可以看到不少RevokeBiasd的紀錄,像GC一樣,會Stop The World的幹活,雖然只是很短很短的停頓,但對於多執行緒併發的應用,取消掉它反而有效能的提升和延時的極微的縮短,所以Cassandra就取消了它。(引自:唯品會資深架構師給你的 JVM 調優建議偏向鎖部分)
- -XX:+TraceBiasedLocking 提供關於BiasedLocking優化的額外的資訊。預設情況下禁用
- -XX:+PrintBiasedLockingStatistics 提供關於BiasedLocking優化的額外的資訊。預設情況下禁用
- -XX:+Inline 啟用內聯方法呼叫,預設情況下啟用
- -XX:+AggressiveOpts 使一些新的優化不預設啟用。如果優化是好的,他們將在下一版本的JDK中啟用
相關文章
- JVM實用引數系列JVM
- JVM調優引數、方法、工具以及案例總結JVM
- JVM實用引數(一)JVM型別以及編譯器模式JVM型別編譯模式
- java jvm 引數 -Xms -Xmx -Xmn -Xss 調優總結JavaJVM
- Table 引數總結
- 常用JVM引數JVM
- jvm引數配置JVM
- parallel rollback引數總結Parallel
- Table 引數總結 (ZT)
- jvm總結JVM
- Mybatis引數處理總結MyBatis
- 引數調整案例總結
- JVM引數以及用法JVM
- 檢視JVM預設引數及微調JVM啟動引數JVM
- SPRING實踐總結--引數註解的使用Spring
- Java基礎學習總結(120)——JVM 引數使用詳細說明JavaJVM
- Python函式引數總結Python函式
- pre_page_sga引數總結
- SpringMVC中的引數繫結總結SpringMVC
- JVM 引數調優(qbit)JVM
- JVM常用調優引數JVM
- JVM引數分享 OmitStackTraceInFastThrowJVMMITAST
- tomcat jvm 引數配置TomcatJVM
- 常用的jvm配置引數 :永久區引數配置JVM
- JVM學習總結JVM
- Flink常用的配置引數總結
- openai GPT引數(入參)使用總結OpenAIGPT
- JVM常見引數設定JVM
- JVM引數設定大氣JVM
- JVM記憶體引數配置JVM記憶體
- 全面輸出JVM配置引數JVM
- 容器化環境中,JVM最佳引數配置實踐JVM
- consul配置引數大全、詳解、總結
- 歸檔日誌命令及引數總結
- 【JVM進階之路】十:JVM調優總結JVM
- 檢視JVM執行時引數JVM
- 檢視JVM預設配置引數JVM
- Windows 下修改Tomcat jvm引數WindowsTomcatJVM