2. 程式人生 > >JVM的GC日誌的主要引數

JVM的GC日誌的主要引數

阿新 • • 發佈：2019-01-23 
-Xmn1024m -Xms2500m -Xmx2500m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:MaxDirectMemorySize=256m -XX:+UseCMSInitiatingOccupancyOnly -XX:SurvivorRatio=8 -XX:+ExplicitGCInvokesConcurrent -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=256m -XX:-OmitStackTraceInFastThrow -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/www/logs/gc-%%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/www/logs -Djava.io.tmpdir=/var/www/tmp

 一:理解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.等等


參考資料:

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

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}   
  7. [zw-34-71 logs]# java -version  
  8. java version "1.7.0_45"  
  9. [zw-34-71 logs]# java -XX:+PrintFlagsInitial | grep MaxTenuringThreshold  
  10. intx MaxTenuringThreshold = 15 {product}  
  11. [zw-34-71 logs]# java -XX:+PrintFlagsFinal -XX:+UseConcMarkSweepGC | grep MaxTenuringThreshold  
  12. 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劃分成物理固定大小，對於不同場景比例應該設定成多少很考驗經驗.

2) 邏輯分代圖(G1)

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


相關推薦

JVM的GC日誌的主要引數

-Xmn1024m -Xms2500m -Xmx2500m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:MaxDirectMemorySize=256m -XX:+UseCMSIniti

運放的主要引數

文章原始地址: http://feotech.com/?p=111 整合運放的引數較多，其中主要引數分為直流指標和交流指標。 1、直流指標又分為： （1）輸入失調電壓VIO：輸入失調電壓定義為整合運放輸出端電壓為零時，兩個 輸入端之間所加的補償電壓。輸入失調電壓實際上反映了運放內部的電路

MongoDB主要引數.md

mongod的主要引數有： dbpath: 資料檔案存放路徑，每個資料庫會在其中建立一個子目錄。用於防止同一個例項多次執行的mongod.lock也儲存在此目錄中。 logpath：錯誤日誌檔案 logappend： 錯誤日誌採用追加模式（預

Kafka主要引數詳解

系統引數 #唯一標識在叢集中的ID，要求是正數。 broker.id=0 #服務埠，預設9092 port=9092 #監聽地址 host.name=debugo01 # 處理網路請求的最大執行緒數 num.network.threads=2 # 處理磁碟I/O的執行緒數

Kafka主要引數詳解server.properties

  一、相關引數配置 ############################ System ############################# #唯一標識在叢集中的ID，要求是正數。 broker.id=0 #服務埠，預設9092 port=9092

MongoDB資料庫中mongod的主要引數

mongod的主要引數有：  基本配置 --------------------------------------------------------------------------------   --quiet # 安靜輸出

springmvc 專案完整示例06 日誌–log4j 引數詳細解析 log4j如何配置

Log4j由三個重要的元件構成： 日誌資訊的優先順序 日誌資訊的輸出目的地 日誌資訊的輸出格式 日誌資訊的優先順序從高到低有ERROR、WARN、 INFO、DEBUG，分別用來指定這條日誌資訊的重要程度； 日誌資訊的輸出目的地指定了日誌將列印到控制檯還是檔案中； 而輸出格式則控制了日誌資訊的顯

建立物化檢視語句主要引數

build build讓你指定什麼時候操作物化檢視 immediate 這個引數指明物化檢視被馬上操作，這個是預設值。 deferred,指明物化檢視在下一次重新整理操作，第一次重新整理必須是完全重新整理，之前的資料是不可用的，不能用於查詢重寫。 create_mv_ref

Executor Framework分析 (二) ThreadPoolExecutor主要引數分析

本篇部落格主要記錄ThreadPoolExecutor主要引數的含義， 並分析相關介面的具體實現。 很多時候，當我們不需要指定執行緒池的執行細節時， 會直接利用工具類Executors建立執行緒池，例如： public class Executo

路由器的型別及衡量路由器效能的主要引數指標

　　網際網路各種級別的網路中隨處都可見到路由器。接入網路使得家庭和小型企業可以連線到某個網際網路服務提供商；企業網中的路由器連線一個校園或企業內成千上萬的計算機；骨幹網上的路由器終端系統通常是不能直接訪問的，它們連線長距離骨幹網上的ISP和企業網路。網際網路的快速發展無論是對骨幹網、企業網還是接入網都帶來

Mysql怎麼判斷繁忙，innodb的主要引數，checkpoint機制,show engine innodb status

show engine innodb status GCheckpoint詳解能夠觸發寫操作的一些因素控制寫入操作前滾和回滾資料庫效能監控效能指標壓力測試的工具資料庫效能相關指標小結show engine innodb status \Gmysql> show en

資料庫連線池介紹、主要引數設定、作用

<bean id="dataSource"               class="org.apache.commons.dbcp.BasicDataSource">               <property name="driverClassName"              

postgresql wal日誌部分引數

fsync fsync ：控制wal日誌重新整理是否開啟重新整理到磁碟,此引數控制wal_sync_method引數的重新整理方法,如果fsync為off,則wal_sync_method的方法是沒有意義的, 如果沒開啟這個引數,則可能由於wal日誌塊沒有重

TVS管主要引數,七大知識點!

　　TVS管其主要特性引數,七大知識點!　　面對廣大的工程師朋友們，TVS管其主要特性引數是必備瞭解的一件工程。那麼對於TVS管其主要特性引數有哪些？今天深圳踏歌電子技術小編在此為大家講述下主要的七大知識：　　1、反向截止電壓 VRWM 與反向漏電流 IR：反向截止電壓 VRWM 表示 TVS 管 不導通的最

鏡頭主要引數與光 源 選 型，選型焦距計算公式。

1.焦距（FocalLength）　　 焦距是從鏡頭的中心點到膠平面上所形成的清晰影像之間的距離。焦距的大小決定著視角的大小，焦距數值小，視角大，所觀察的範圍也大；焦距數值大，視角小，觀察範圍小。根據焦距能否調節，可分為定焦鏡頭和變焦鏡頭兩大類。　　 2.光圈(Iris)　

LCD1602主要引數,引腳功能及初始化方法

LCD1602主要引數,引腳功能 及初始化方法 LCD1602液晶 顯示模組基本技術：  1）、主要功能 A、 40通道點陣LCD 驅動; B、 可選擇當作行驅動或列驅動; C、 輸入/輸出訊號

jfinal中日誌輸入請求引數連結

LogKit.info("Request:" + inv.getActionKey() + "?" + UrlUtil.formatMap(inv.getController())); public static String formatMap(Controller c) { String

日誌資訊新增和引數校驗

1：在類中要新增日誌資訊： private static final Logger log = LogManager.getLogger(ShopCartAction.class); log.info();//普通訊息 log.error();//錯誤資訊列印 log.debug()

Linux系統中各種系統日誌檔案主要存放在系統中哪個目錄

/var/log/message 系統啟動後的資訊和錯誤日誌，是Red Hat Linux中最常用的日誌之一 /var/log/secure 與安全相關的日誌資訊 /var/log/maillog 與郵件相關的日誌資訊 /var/log/cron 與定時任務相關的日誌資訊 /va

AOP日誌元件 多次獲取post引數

AOP日誌元件 多次獲取post引數 需求：新增介面日誌元件。通過攔截器對介面URL進行攔截處理，然後將介面post請求的引數與結果，寫入日誌表。 問題：POST方法的引數是儲存在request.getInputStream中，只能讀一次，不能多次讀取。從中讀取post