2. 程式人生 > >JVM日誌和參數的理解

JVM日誌和參數的理解

阿新 • • 發佈：2018-07-09
detail icon doc san 圖片 spa 需要 算法 times

寫這篇wiki的目的:最近在調整Hbase的JVM,翻了些文檔和wiki,想寫點東西,給自己和想了解jvm日誌和參數的同 學提供些幫助.

一:理解GC日誌格式,讀GC日誌的方法

1:開啟日誌

-verbose:gc

-XX:+PrintGCDetails

-XX:+PrintGCDateStamps

-Xloggc:/path/gc.log

-XX:+UseGCLogFileRotation 啟用GC日誌文件的自動轉儲 (Since Java)

-XX:NumberOfGClogFiles=1 GC日誌文件的循環數目 (Since Java)

-XX:GCLogFileSize=1M 控制GC日誌文件的大小 (Since Java)

-XX:+PrintGC包含-verbose:gc

-XX:+PrintGCDetails //包含-XX:+PrintGC

只要設置-XX:+PrintGCDetails 就會自動帶上-verbose:gc和-XX:+PrintGC

-XX:+PrintGCDateStamps/-XX:+PrintGCTimeStamps 輸出gc的觸發時間

2:新生代(Young GC)gc日誌分析

Java代碼 技術分享圖片
  1. 2014-02-28T11:59:00.638+0800: 766.537:[GC2014-02-28T11:59:00.638+0800: 766.537:
  2. [ParNew: 1770882K->212916K(1835008K), 0.0834220 secs]
  3. 5240418K->3814487K(24903680K), 0.0837310 secs] [Times: user=1.12 sys=0.02, real=0.08 secs]

2014-02-28T11:59:00 ...（時間戳）:[GC（Young GC）（時間戳）:[ParNew（使用ParNew作為年輕代的垃圾回收期）:

1770882K（年輕代垃圾回收前的大小）->212916K（年輕代垃圾回收以後的大小）(1835008K)（年輕代的capacity）, 0.0834220 secs（回收時間）]
5240418K（整個heap垃圾回收前的大小）->3814487K（整個heap垃圾回收後的大小）(24903680K)（heap的capacity）, 0.0837310secs（回收時間）]

[Times: user=1.12（Young GC用戶耗時） sys=0.02（Young GC系統耗時）, real=0.08 secs（Young GC實際耗時）]

其中 Young GC回收了1770882-212916=1557966K內存
Heap通過這次回收總共減少了 5240418-3814487=1425931 K的內存。1557966-1425931=132035K說明這次Young GC有約128M的內存被移動到了Old Gen，
提示:進代量(Young->Old)需要重點觀察，預防promotion failed.

3:老年代(CMS old gc)分析

Java代碼 技術分享圖片
  1. 2014-02-28T23:58:42.314+0800: 25789.661: [GC [1 CMS-initial-mark: 17303356K(23068672K)] 18642315K(24903680K), 1.0400410 secs] [Times: user=1.04 sys=0.00, real=1.04 secs]
  2. 2014-02-28T23:58:43.354+0800: 25790.701: [CMS-concurrent-mark-start]
  3. 2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-mark: 0.315/0.363 secs] [Times: user=1.64 sys=0.02, real=0.37 secs]
  4. 2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-preclean-start]
  5. 2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-preclean: 0.181/0.190 secs] [Times: user=0.20 sys=0.01, real=0.19 secs]
  6. 2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-abortable-preclean-start]
  7. CMS: abort preclean due to time 2014-02-28T23:58:49.082+0800: 25796.429: [CMS-concurrent-abortable-preclean: 5.165/5.174 secs] [Times: user=5.40 sys=0.04, real=5.17 secs]
  8. 2014-02-28T23:58:49.083+0800: 25796.430: [GC[YG occupancy: 1365142 K (1835008 K)]2014-02-28T23:58:49.083+0800: 25796.430: [Rescan (parallel) , 0.9690640 secs]2014-02-28T23:58:50.052+0800: 25797.399: [weak refs processing, 0.0006190 secs]2014-02-28T23:58:50.053+0800: 25797.400: [scrub string table, 0.0006290 secs] [1 CMS-remark: 17355150K(23068672K)] 18720292K(24903680K), 0.9706650 secs] [Times: user=16.49 sys=0.06, real=0.97 secs]
  9. 2014-02-28T23:58:50.054+0800: 25797.401: [CMS-concurrent-sweep-start]
  10. 2014-02-28T23:58:51.940+0800: 25799.287: [CMS-concurrent-sweep: 1.875/1.887 secs] [Times: user=2.03 sys=0.03, real=1.89 secs]
  11. 2014-02-28T23:58:51.941+0800: 25799.288: [CMS-concurrent-reset-start]
  12. 2014-02-28T23:58:52.067+0800: 25799.414: [CMS-concurrent-reset: 0.127/0.127 secs] [Times: user=0.13 sys=0.00, real=0.13 secs]
  13. 2014-03-01T00:00:36.293+0800: 25903.640: [GC2014-03-01T00:00:36.293+0800: 25903.640: [ParNew: 1805234K->226801K(1835008K), 0.1020510 secs] 10902912K->9434796K(24903680K), 0.1023150 secs] [Times: user=1.35 sys=0.02, real=0.10 secs]
  14. 2014-03-01T00:07:13.559+0800: 26300.906: [GC2014-03-01T00:07:13.559+0800: 26300.906: [ParNew: 1799665K->248991K(1835008K), 0.0876870 secs] 14086673K->12612462K(24903680K), 0.0879620 secs] [Times: user=1.24 sys=0.01, real=0.09 secs]

CMS的gc日誌分為一下幾個步驟，重點關註initial-mark和remark這兩個階段，因為這兩個階段會stop進程。

初始標記（init mark）：收集根引用，這是一個stop-the-world階段。

並發標記（concurrent mark）：這個階段可以和用戶應用並發進行。遍歷老年代的對象圖，標記出活著的對象。

並發預清理（concurrent preclean）：這同樣是一個並發的階段。主要的用途也是用來標記，用來標記那些在前面標記之後，發生變化的引用。主要是為了縮短remark階段的stop-the-world的時間。

重新標記（remark）：這是一個stop-the-world的操作。暫停各個應用，統計那些在發生變化的標記。

並發清理（concurrent sweep）：並發掃描整個老年代，回收一些在對象圖中不可達對象所占用的空間。

並發重置（concurrent reset）：重置某些數據結果，以備下一個回收周期

提示:紅色為全部暫停階段,重點關註.

Java代碼 技術分享圖片
  1. [GC [1 CMS-initial-mark: 17303356K(23068672K)] 18642315K(24903680K), 1.0400410 secs] [Times: user=1.04 sys=0.00, real=1.04 secs]

其中數字依表示標記前後old區的所有對象占內存大小和old的capacity，整個JavaHeap（不包括perm）所有對象占內存總的大小和JavaHeap的capacity。

Java代碼 技術分享圖片
  1. [GC[YG occupancy: 1365142 K (1835008 K)]2014-02-28T23:58:49.083+0800: 25796.430:
  2. [Rescan (parallel) , 0.9690640 secs]2014-02-28T23:58:50.052+0800: 25797.399:
  3. [weak refs processing, 0.0006190 secs]2014-02-28T23:58:50.053+0800: 25797.400: [scrub string table, 0.0006290 secs]
  4. [1 CMS-remark: 17355150K(23068672K)] 18720292K(24903680K), 0.9706650 secs] [Times: user=16.49 sys=0.06, real=0.97 secs]

Rescan (parallel)表示的是多線程處理young區和多線程掃描old+perm的總時間， parallel 表示多GC線程並行。

weak refs processing 處理old區的弱引用的總時間，用於回收native memory.等等


參考資料:

https://blogs.oracle.com/jonthecollector/entry/the_unspoken_cms_and_printgcdetails

https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

4:老年代(CMS old GC ) concurrent mode failure日誌

Java代碼 技術分享圖片
  1. 2014-03-03T09:38:26.457+0800: 233373.804: [GC [1 CMS-initial-mark: 17319615K(23068672K)] 17351070K(24903680K), 0.0419440 secs]
  2. [Times: user=0.04 sys=0.00, real=0.04 secs]
  3. 2014-03-03T09:38:26.499+0800: 233373.846: [CMS-concurrent-mark-start]
  4. 2014-03-03T09:38:28.175+0800: 233375.522: [GC2014-03-03T09:38:28.175+0800: 233375.522: [CMS2014-03-03T09:38:28.887+0800: 233376.234:
  5. [CMS-concurrent-mark: 1.989/2.388 secs] [Times: user=14.37 sys=0.24, real=2.39 secs]
  6. (concurrent mode failure): 17473174K->8394653K(23068672K), 19.3309170 secs] 18319691K->8394653K(24903680K),
  7. [CMS Perm : 23157K->23154K(98304K)], 19.3311700 secs] [Times: user=22.18 sys=0.00, real=19.33 secs]

concurrent mode failure一般發生在CMS GC 運行過程中,老年代空間不足，引發MSC(Full GC)

上面的這條發日誌說明CMS運行到CMS-concurrent-mark過程中就出現空間不足,產生並發失敗(17319615K(23068672K)占77%),


解決思路：降低YGC頻率，降低CMS GC觸發時機,適當降低CMSInitiatingOccupancyFraction.

5:新生代(ParNew YGC)promotion failed日誌

Java代碼 技術分享圖片
  1. 2014-02-27T21:19:42.460+0800: 210095.040: [GC 210095.040: [ParNew (promotion failed): 1887487K->1887488K(1887488K), 0.4818790 secs]210095.522: [CMS: 13706434K->7942818K(23068672K), 9.7152990 secs] 15358303K->7942818K(24956160K), [CMS Perm : 27424K->27373K(98304K)], 10.1974110 secs] [Times: user=12.06 sys=0.01, real=10.20 secs]

promotion failed一般發生在新生代晉升老年代時,老年代空間不夠或連續空間不夠卻還沒達到old區的觸發值,引發Full Gc.

解決思路:由於heap碎片,YGC晉升對象過大,過長.(mid/long Time Object),調整-XX:PretenureSizeThreshold=65535,-XX:MaxTenuringThreshold=6

6:system.gc()產生的Full GC日誌

Java代碼 技術分享圖片
  1. <strong>2014-01-21T17:44:01.554+0800: 50212.568: [Full GC (System) 50212.568:
  2. [CMS: 943772K220K(2596864K), 2.3424070 secs] 1477000K->220K(4061184K), [CMS Perm : 3361K->3361K(98304K)], 2.3425410 secs] [Times: user=2.33 sys=0.01, real=2.34 secs]</strong>

Full GC (System)意味著這是個system.gc調用產生的MSC。
“943772K->220K(2596864K), 2.3424070 secs”表示：這次MSC前後old區內總對象大小，old的capacity及這次MSC耗時。
“1477000K->220K(4061184K)”表示：這次MSC前後JavaHeap內總對象大小，JavaHeap的capacity。
“3361K->3361K(98304K)], 2.3425410 secs”表示：這次MSC前後Perm區內總對象大小，Perm區的capacity。


解決:
使用-XX:+DisableExplicitGC參數，System.gc()會變成空調用.
如果應用有地方大量使用direct memory 或 rmi，那麽使用-XX:+DisableExplicitGC要小心。
可以使用-XX:+ExplicitGCInvokesConcurrent替換把 System.gc()從Full GC換成CMS GC.

原因:
DirectByteBuffer沒有finalizer，native memory的清理工作是通過sun.misc.Cleaner自動完成
sun.misc.Cleaner是基於PhantomReference的清理工具,Full GC/Old GC會對old gen做reference processing，同時觸發Cleaner對已死的DirectByteBuffer對象做清理。
如果長時間沒有GC或者只做了young GC的話,不會觸發old區Cleaner的工作，容易產生DirectMemory OOM.
參考:https://gist.github.com/rednaxelafx/1614952

RMI會做的是分布式GC。Sun JDK的分布式GC是用純Java實現的,為RMI服務。
參考:http://docs.oracle.com/javase/6/docs/technotes/guides/rmi/sunrmiproperties.html

7:特殊的Full GC日誌,根據動態計算直接進行MSC

Java代碼 技術分享圖片
  1. 2014-02-13T13:48:06.349+0800: 7.092: [GC 7.092: [ParNew: 471872K->471872K(471872K), 0.0000420 secs]7.092: [CMS: 366666K->524287K(524288K), 27.0023450 secs] 838538K->829914K(996160K), [CMS Perm : 3196K->3195K(131072K)], 27.0025170 secs]

ParNew的時間特別短，jvm在minor gc前會首先確認old是不是足夠大，如果不夠大，這次young gc直接返回，進行MSC(Full GC)。

二:參數配置和理解

1:參數分類和說明

jvm參數分固定參數和非固定參數

1):固定參數

如：-Xmx,-Xms,-Xmn,-Xss.

2):非固定參數

如:

-XX:+<option> 啟用選項

-XX:-<option> 不啟用選項

-XX:<option>=<number> 給選項設置一個數字類型值，可跟單位，例如 128k, 2g

-XX:<option>=<string> 給選項設置一個字符串值，例如-XX:HeapDumpPath=./dump.log

2:JVM可設置參數和默認值

1):-XX:+PrintCommandLineFlags

打印出JVM初始化完畢後所有跟最初的默認值不同的參數及它們的值,jdk1.5後支持.

線上建議打開，可以看到自己改了哪些值.

2):-XX:+PrintFlagsFinal

顯示所有可設置的參數及"參數處理"後的默認值。參數本身只從JDK6 U21後支持

可是查看不同版本默認值,以及是否設置成功.輸出的信息中"="表示使用的是初始默認值，而":="表示使用的不是初始默認值

如:jdk6/7 -XX:+MaxTenuringThreshold 默認值都是15,但是在使用CMS收集器後,jdk6默認4 , jdk7默認6.

Java代碼 技術分享圖片
  1. [hbase96 logs]# java -version
  2. java version "1.6.0_27-ea"
  3. [hbase96 logs]# java -XX:+PrintFlagsInitial | grep MaxTenuringThreshold
  4. intx MaxTenuringThreshold = 15 {product}
  5. [hbase96 logs]# java -XX:+PrintFlagsFinal -XX:+UseConcMarkSweepGC | grep MaxTenuringThreshold
  6. intx MaxTenuringThreshold := 4 {product}
  8. [zw-34-71 logs]# java -version
  9. java version "1.7.0_45"
  10. [zw-34-71 logs]# java -XX:+PrintFlagsInitial | grep MaxTenuringThreshold
  11. intx MaxTenuringThreshold = 15 {product}
  12. [zw-34-71 logs]# java -XX:+PrintFlagsFinal -XX:+UseConcMarkSweepGC | grep MaxTenuringThreshold
  13. intx MaxTenuringThreshold := 6 {product}

3):-XX:+PrintFlagsInitial

在"參數處理"之前所有可設置的參數及它們的值,然後直接退出程序.

這裏的"參數處理"指: 檢查參數之間是否有沖突,通過ergonomics調整某些參數的值等.

Java代碼 技術分享圖片
  1. [hbase96 logs]# java -version
  2. java version "1.6.0_27-ea"
  3. [hbase96 logs]# java -XX:+PrintFlagsInitial | grep UseCompressedOops
  4. bool UseCompressedOops = false {lp64_product}
  5. [hbase96 logs]# java -XX:+PrintFlagsFinal | grep UseCompressedOops
  6. bool UseCompressedOops := true {lp64_product}

4)CMSInitiatingOccupancyFraction 默認值是多少

jdk6/7:

Java代碼 技術分享圖片
  1. #java -server -XX:+UseConcMarkSweepGC -XX:+PrintFlagsFinal | grep -P "CMSInitiatingOccupancyFraction|CMSTriggerRatio|MinHeapFreeRatio"
  2. intx CMSInitiatingOccupancyFraction = -1 {product}
  3. intx CMSTriggerRatio = 80 {product}
  4. uintx MinHeapFreeRatio = 40 {product}

計算公式:

CMSInitiatingOccupancyFraction = (100 - MinHeapFreeRatio) + (CMSTriggerRatio * MinHeapFreeRatio / 100)

最終結果: 在jdk6/7中 CMSInitiatingOccupancyFraction默認值是92% .不是網上傳的68%; 都這麽傳,是因為 "深入理解Java虛擬機"一書中是68%,但它用的是jdk5 , jdk5的CMSTriggerRatio默認值是20,坑爹...

三:JVM內存區域理解和相關參數

一圖勝千言,直接上圖

1):物理分代圖.

技術分享圖片

物理分代是除G1之外的JVM 內存分配方式,jvm 通過-Xmx,-Xmn/newRatio等參數將jvm heap劃分成物理固定大小，對於不同場景比例應該設置成多少很考驗經驗.

一篇JVM CMS優化講解的非常好的文章: how-tame-java-gc-pauses

2) 邏輯分代圖(G1)

技術分享圖片

邏輯分代是以後的趨勢(PS:jdk8連perm都不區分了。)， 不需要使用者在糾結Xms/Xmn,SurvivorRatio等比例問題,采用動態算法調整分代大小。

JVM日誌和參數的理解

相關推薦

JVM日誌和參數的理解

detail icon doc san 圖片 spa 需要 算法 times 寫這篇wiki的目的:最近在調整Hbase的JVM,翻了些文檔和wiki,想寫點東西,給自己和想了解jvm日誌和參數的同 學提供些幫助. 一:理解GC日誌格式,讀GC日誌的方法 1:

記錄一次線程池的在項目中的實際應用，講解一下線程池的配置和參數理解。

div pro 繼續 bstr warn fin autowire string ping 前言：最近項目中與融360項目中接口對接，有反饋接口（也就是我們接收到請求，需要立即響應，並且還要有一個接口推送給他們其他計算結果），推送過程耗時、或者說兩個接口不能是同時返回，有先

netty和jvm 虛擬機參數的 XX:+DisableExplicitGC 註意事項

nat 釋放 mod 區域 內存溢出 () 註意事項 關聯 -a 在使用netty時，經常出現內存溢出，經查詢是這個坑： netty 使用的nio 和 jvm 中的 XX:+DisableExplicitGC配置的沖突導致的，具體經過：nio 使用直接內存區域 Di

[shell]簡單的shell提示和參數腳本

log help pre col home bsp 腳本 $1 是否 該shell腳本有如下點： bash or dash case語句的寫法 腳本help寫法 參數是否為空的寫法 參數 #! /bin/bash case "$1" in -h|--help

struts2 全局攔截器，顯示請求方法和參數

功能 defaults i18n token override params tin back alias 後臺系統中應該須要一個功能那就是將每一個請求的url地址和請求的參數log出來，方便系統調試和bug追蹤，使用struts2時能夠使用struts2的全局攔截器實

筆記：MyBatis Mapper XML文件詳解 - 映射和參數

gin server 頂級 ctp columns ref acl 目標 對象傳遞 MyBatis 的真正強大在於它的映射語句，也是它的魔力所在。由於它的異常強大，映射器的 XML 文件就顯得相對簡單。如果拿它跟具有相同功能的 JDBC 代碼進行對比，你會立即發現省掉了將近

將方法作為方法的參數 —— 理解托付

case eight ace 說我 watermark enter 接受 stat 正常 《.NET開發之美》上對於托付寫到：“它們就像是一道檻兒，過了這個檻的人，認為真是太easy了，而沒有過去的人每次見到托付和事件就認為心裏別得慌，混身不自在。”我認為這句話就像是在

17）PHP，函數基礎和參數問題

個數 str fun ont 數據 ges 實參 col 返回 （1）函數定義形式： 　　　　　　　　 1 function 函數名字（形參1，形參2，形參3.。。。。。。。） 2 { 3 4

使用URI獲取鏈接和參數

cal instance lin hello str rem pri doc tps https://medialize.github.io/URI.js/docs.html#accessors-hostname 這個是參考文檔的地址 var uri = new URI(

python函數參數理解

cti 註意 ins style 默認參數 參數 python 多次調用 def 1、位置參數 　　函數調用時，參數賦值按照位置順序依次賦值。 　　e.g. 1 def function(x): 2 3　　return x * x 4 5 print functio

js的參數理解

rip define span 長度 函數 cti col 自動 決定 ECMAScript內的參數在內部使用一個數組來表示的，在函數內可以通過arguments對象來訪問這個參數數組，從而傳遞給函數的每一個參數 function doADD () { if (a

df命令和參數詳解

df 分區信息 分區空間 df -i輸出文件系統的 inode 信息，如果iNode滿了，即使有空間也不能存儲df -h以人類易讀的格式輸出df -a顯示所有文件系統的磁盤使用情況df -h /boot顯示特定文件系統已使用的空間df -T輸出所有已掛載文件系統的類型df -k按塊大小輸出文件

flask中的session,render_template()第二和參數是字典

ren 字典 保險 登入 com session nbsp ssi png 1. 設置一個secret_key 2.驗證登入後加上session,這是最簡單,不保險 . 3.註意render_template傳的參數是字典 flask中的session,render_

學習TensorFlow，TensorBoard可視化網絡結構和參數

pla code ext world hold 技巧 n) sample 化工 在學習深度網絡框架的過程中，我們發現一個問題，就是如何輸出各層網絡參數，用於更好地理解，調試和優化網絡？針對這個問題，TensorFlow開發了一個特別有用的可視化工具包：TensorBoard

使用maven時，如何修改JVM的配置參數；maven命令執行時到底消耗多少內存？

option oca sin port more https exe exc style maven是使用java啟動的，因此依賴JVM，那麽如何修改JVM參數？ MAVEN_OPTS 在系統的環境變量中，設置MAVEN_OPTS，用以存放JVM的參數，具體設置的步

jvm 虛擬機參數_堆內存分配

永久 shared fig println configure oid tro 日誌 大堆 1、參數 -XX:+PrintGC 只要遇到 GC 就會打印日誌 -XX:+UseSerialGC 配置串行回收器 -XX:+PrintGCDetails 查看詳

C#通過反射獲取類中的方法和參數個數，反射調用方法帶參數

new [] 反射 電腦 ram col sta body create using System; using System.Reflection; namespace ConsoleApp2 { class Program { sta

C#異步執行帶有返回值和參數的方法，且獲取返回值

urn 利用 回調方法 ext col list ont mes gate 很多時候需要用到這些小知識點，做做筆記一起成長 下面是需要異步執行的方法 //獲取所有的郵件 private List<EmailModel> GetEmailOnl

Django之ORM字段和參數

spl ace 數據庫表 time() 範圍 digits 查詢 allow 連接 字段 常用字段 AutoField

vim的基本用法和參數

Linux 學習 參數 VIM簡介vi: Visual Interface，文本編輯器 文本：ASCII, Unicode 文本編輯種類： 行編輯器: sed 全屏編輯器：nano, vi vim - Vi Improved 其他編輯器： gedit 一個簡單的圖形編輯器 gvim