實用 JVM 引數總結

VikingBird發表於2016-12-26

摘要: 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中啟用

相關文章