Java GC日志查看與分析

一. JVM的GC日志主要參數(shù)包括如下:

-XX:+PrintGC 輸出GC日志
-XX:+PrintGCDetails 輸出GC的詳細(xì)日志
-XX:+PrintGCTimeStamps 輸出GC的時(shí)間戳(以基準(zhǔn)時(shí)間的形式)
-XX:+PrintGCDateStamps 輸出GC的時(shí)間戳(以日期的形式徘禁,如 2018-09-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在進(jìn)行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的輸出路徑

eg.
windows下面配置VM參數(shù)如下:

-XX:+PrintGCDetails -Xloggc:E:\workspace\workspace_java_tool\workspace_sunny_project\java-honey-collection\logs\gc.log -XX:+PrintGCTimeStamps  

Linux配置VM參數(shù)如下:

-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:./logs/gc.log  

使用idea配置VM參數(shù)步驟:

image.png

image.png

執(zhí)行ReferenceCountingGC.java之后挣柬,
image.png

gc日志輸出如下:

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for windows-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8240184k(2720372k free), swap 18201656k(8980516k free)
CommandLine flags: -XX:InitialHeapSize=131842944 -XX:MaxHeapSize=2109487104 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
0.490: [GC (System.gc()) [PSYoungGen: 9377K->1573K(37888K)] 9377K->1581K(123904K), 0.0016584 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.491: [Full GC (System.gc()) [PSYoungGen: 1573K->0K(37888K)] [ParOldGen: 8K->1447K(86016K)] 1581K->1447K(123904K), [Metaspace: 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 37888K, used 328K [0x00000000d6180000, 0x00000000d8b80000, 0x0000000100000000)
  eden space 32768K, 1% used [0x00000000d6180000,0x00000000d61d2030,0x00000000d8180000)
  from space 5120K, 0% used [0x00000000d8180000,0x00000000d8180000,0x00000000d8680000)
  to   space 5120K, 0% used [0x00000000d8680000,0x00000000d8680000,0x00000000d8b80000)
 ParOldGen       total 86016K, used 1447K [0x0000000082400000, 0x0000000087800000, 0x00000000d6180000)
  object space 86016K, 1% used [0x0000000082400000,0x0000000082569f40,0x0000000087800000)
 Metaspace       used 3538K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 385K, capacity 388K, committed 512K, reserved 1048576K

二. GC日志解析

0.490: [GC (System.gc()) [PSYoungGen: 9377K->1573K(37888K)] 9377K->1581K(123904K), 0.0016584 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.491: [Full GC (System.gc()) [PSYoungGen: 1573K->0K(37888K)] [ParOldGen: 8K->1447K(86016K)] 1581K->1447K(123904K), [Metaspace: 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 

?他們分別顯示了JVM GC的過(guò)程,清理出了多少空間掀鹅。第一行GC使用的是‘普通GC’(MinorCollections)蕉饼,第二行使用的是‘全GC’(MajorCollections)歉嗓。他們的區(qū)別很大妆兑,在第一行最后我們可以看見(jiàn)他的時(shí)間是real=0.00 secs力试,而第二行的FullGC的時(shí)間是 real=0.01 secs贮预。第二行耗費(fèi)的時(shí)間明顯比第一個(gè)多很多贝室,也就是我們調(diào)優(yōu)的重點(diǎn),減少FullGC的次數(shù)仿吞,以為FullGC會(huì)暫停程序比較長(zhǎng)的時(shí)間滑频,如果FullGC的次數(shù)比較多。程序就會(huì)經(jīng)常性的假死唤冈。
?第一行:PSYoungGen峡迷、ParOldGenPSPermGen屬于Parallel收集器你虹。其中PSYoungGen表示gc回收前后年輕代的內(nèi)存變化绘搞;ParOldGen表示gc回收前后老年代的內(nèi)存變化;PSPermGen表示gc回收前后永久區(qū)的內(nèi)存變化傅物;如果是Serial收集器中的新生代名為“Default New Generation”夯辖,則會(huì)顯示DefNew; 緊跟后面的 9377K->1573K(37888K) 中的 9377K代表young generation 回收前大小,1573K代表回收后大小董饰,括號(hào)中的37888K 代表young generation總大小(包含2個(gè)survivor)蒿褂;9377K->1581K(123904K)則代表整個(gè)Heap(young+old)的變化與總量;Times: user=0.00 sys=0.00, real=0.00 secs: user代表GC 需要的各個(gè)CPU總時(shí)間(各個(gè)CPU時(shí)間相加)卒暂,sys代表回收器自身的行為所占用CPU時(shí)間啄栓,real則代表本次GC所耗費(fèi)的真正耗時(shí)(在多核CPU中并行回收,它通常小于user) 也祠。
?第二行:Full GC即代表 Major GC, 0.491(JVM 啟動(dòng)后經(jīng)過(guò)的時(shí)間昙楚,單位為秒): [Full GC (System.gc()(導(dǎo)致 GC 的原因,這里是手動(dòng)調(diào)用System.gc()導(dǎo)致的)) [PSYoungGen(Parallel GC 年輕代內(nèi)存區(qū)域名稱(chēng)齿坷,并行桂肌,多線(xiàn)程,標(biāo)記-復(fù)制 Mark-Copy永淌,STW): PSYoungGen(GC前年輕代的使用量)->0K(GC 前后輕代的使用量)(37888K(年輕代總大小)] [ParOldGen(Parallel GC 老年代內(nèi)存區(qū)域名稱(chēng)崎场,并行,多線(xiàn)程遂蛀,標(biāo)記-清除-整理 Mark-Sweep-Compact谭跨,STW): 8K(GC 前老年代的使用量)->1447K(GC 后老年代的使用量)(86016K(老年代代總大小))] 1581K(GC 前整個(gè)堆的使用量)->1447K(GC 后整個(gè)堆的使用量)(123904K(整個(gè)堆的總大小)),[Metaspace(Parallel Scavenge收集器配套的永久代): 3530K->3530K(1056768K)], 0.0068323 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

?注意:1. 在 Parallel GC 中螃宙,real 約等于 (user + sys) / GC 線(xiàn)程數(shù)蛮瞄。請(qǐng)注意,總有一定比例的處理過(guò)程是不能并行進(jìn)行的; 2. 年輕代的使用量從 524800K 變?yōu)?0K谆扎,一般 Full GC 的結(jié)果都是這樣; 3. 老年代沒(méi)有減挂捅,反而增加,是因?yàn)槟贻p代中沒(méi)有被清除的對(duì)象被提升到了老年代

三. 案例

In this post, we will review how garbage collector logs look like and what useful information one can obtain from them. For this purpose, we have turned on GC logging for a JVM running with -XX:+UseSerialGC by using the following startup parameters:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

This resulted in the output similar to following:

2015-05-26T14:45:37.987-0200: 151.126: [GC (Allocation Failure) 151.126: [DefNew: 629119K->69888K(629120K), 0.0584157 secs] 1619346K->1273247K(2027264K), 0.0585007 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
2015-05-26T14:45:59.690-0200: 172.829: [GC (Allocation Failure) 172.829: [DefNew: 629120K->629120K(629120K), 0.0000372 secs]172.829: [Tenured: 1203359K->755802K(1398144K), 0.1855567 secs] 1832479K->755802K(2027264K), [Metaspace: 6741K->6741K(1056768K)], 0.1856954 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]

The above short snippet from the GC logs exposes a lot of information about what is going on inside the JVM. As a matter of fact, in this snippet there were two Garbage Collection events taking place, one of them cleaning Young generation and the other one taking care of entire heap. Lets look at the first one of these events, a minor GC, taking place in Young generation:

2015-05-26T14:45:37.987-02001:151.1262:[GC3(Allocation Failure4) 151.126: [DefNew5:629119K->69888K6(629120K)7, 0.0584157 secs]1619346K->1273247K8(2027264K)9,0.0585007 secs10][Times: user=0.06 sys=0.00, real=0.06 secs]11

  1. 2015-05-26T14:45:37.987-0200– Time when the GC event started.
  2. 151.126 – Time when the GC event started, relative to the JVM startup time. Measured in seconds.
  3. GC – Flag to distinguish between Minor & Full GC. This time it is indicating that this was a Minor GC.
  4. Allocation Failure – Cause of the collection. In this case, the GC is triggered due to a data structure not fitting into any region in Young Generation.
  5. DefNew – Name of the garbage collector used. This cryptic name stands for the single-threaded mark-copy stop-the-world garbage collector used to clean Young generation.
  6. 629119K->69888K – Usage of Young generation before and after collection.
  7. (629120K)– Total size of the Young generation.
  8. 1619346K->1273247K– Total used heap before and after collection.
  9. (2027264K) – Total available heap.
  10. 0.0585007 secs– Duration of the GC event in seconds.
  11. [Times: user=0.06 sys=0.00, real=0.06 secs]– Duration of the GC event, measured in different categories:
    • user – Total CPU time that was consumed by Garbage Collector threads during this collection
    • sys – Time spent in OS calls or waiting for system event
    • real – Clock time for which your application was stopped. As Serial Garbage Collectoralways uses just a single thread, real time is thus equal to the sum of user and system times.

From the above snippet we can understand exactly what was happening with memory consumption inside the JVM during the GC event. Before this collection heap usage totaled at 1,619,346K. Out of this amount, the Young generation consumed 629,119K. From this we can calculate the Old generation usage being equal to 990,227K.

A more important conclusion is hidden in the next batch of numbers, indicating that after the collection young generation usage decreased by 559,231K, but total heap usage decreased only by 346,099K. From this we can again derive that 213,132K of objects had been promoted from Young generation to Old.

This GC event can be illustrated with the following snapshots depicting memory usage right before the GC started and right after it finished:

Serial GC Young Gen Java

參考

Understanding Garbage Collection Logs

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
  • 序言:七十年代末堂湖,一起剝皮案震驚了整個(gè)濱河市闲先,隨后出現(xiàn)的幾起案子,更是在濱河造成了極大的恐慌无蜂,老刑警劉巖伺糠,帶你破解...
    沈念sama閱讀 211,639評(píng)論 6 492
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件,死亡現(xiàn)場(chǎng)離奇詭異斥季,居然都是意外死亡训桶,警方通過(guò)查閱死者的電腦和手機(jī),發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 90,277評(píng)論 3 385
  • 文/潘曉璐 我一進(jìn)店門(mén)酣倾,熙熙樓的掌柜王于貴愁眉苦臉地迎上來(lái)舵揭,“玉大人,你說(shuō)我怎么就攤上這事灶挟×鹦啵” “怎么了?”我有些...
    開(kāi)封第一講書(shū)人閱讀 157,221評(píng)論 0 348
  • 文/不壞的土叔 我叫張陵稚铣,是天一觀的道長(zhǎng)箱叁。 經(jīng)常有香客問(wèn)我,道長(zhǎng)惕医,這世上最難降的妖魔是什么耕漱? 我笑而不...
    開(kāi)封第一講書(shū)人閱讀 56,474評(píng)論 1 283
  • 正文 為了忘掉前任,我火速辦了婚禮抬伺,結(jié)果婚禮上螟够,老公的妹妹穿的比我還像新娘。我一直安慰自己峡钓,他們只是感情好妓笙,可當(dāng)我...
    茶點(diǎn)故事閱讀 65,570評(píng)論 6 386
  • 文/花漫 我一把揭開(kāi)白布。 她就那樣靜靜地躺著能岩,像睡著了一般寞宫。 火紅的嫁衣襯著肌膚如雪。 梳的紋絲不亂的頭發(fā)上拉鹃,一...
    開(kāi)封第一講書(shū)人閱讀 49,816評(píng)論 1 290
  • 那天辈赋,我揣著相機(jī)與錄音鲫忍,去河邊找鬼。 笑死钥屈,一個(gè)胖子當(dāng)著我的面吹牛悟民,可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播篷就,決...
    沈念sama閱讀 38,957評(píng)論 3 408
  • 文/蒼蘭香墨 我猛地睜開(kāi)眼射亏,長(zhǎng)吁一口氣:“原來(lái)是場(chǎng)噩夢(mèng)啊……” “哼!你這毒婦竟也來(lái)了腻脏?” 一聲冷哼從身側(cè)響起鸦泳,我...
    開(kāi)封第一講書(shū)人閱讀 37,718評(píng)論 0 266
  • 序言:老撾萬(wàn)榮一對(duì)情侶失蹤,失蹤者是張志新(化名)和其女友劉穎永品,沒(méi)想到半個(gè)月后,有當(dāng)?shù)厝嗽跇?shù)林里發(fā)現(xiàn)了一具尸體击纬,經(jīng)...
    沈念sama閱讀 44,176評(píng)論 1 303
  • 正文 獨(dú)居荒郊野嶺守林人離奇死亡鼎姐,尸身上長(zhǎng)有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點(diǎn)故事閱讀 36,511評(píng)論 2 327
  • 正文 我和宋清朗相戀三年,在試婚紗的時(shí)候發(fā)現(xiàn)自己被綠了更振。 大學(xué)時(shí)的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片炕桨。...
    茶點(diǎn)故事閱讀 38,646評(píng)論 1 340
  • 序言:一個(gè)原本活蹦亂跳的男人離奇死亡,死狀恐怖肯腕,靈堂內(nèi)的尸體忽然破棺而出献宫,到底是詐尸還是另有隱情,我是刑警寧澤实撒,帶...
    沈念sama閱讀 34,322評(píng)論 4 330
  • 正文 年R本政府宣布姊途,位于F島的核電站,受9級(jí)特大地震影響知态,放射性物質(zhì)發(fā)生泄漏捷兰。R本人自食惡果不足惜,卻給世界環(huán)境...
    茶點(diǎn)故事閱讀 39,934評(píng)論 3 313
  • 文/蒙蒙 一负敏、第九天 我趴在偏房一處隱蔽的房頂上張望贡茅。 院中可真熱鬧,春花似錦其做、人聲如沸顶考。這莊子的主人今日做“春日...
    開(kāi)封第一講書(shū)人閱讀 30,755評(píng)論 0 21
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽(yáng)驹沿。三九已至,卻和暖如春浮庐,著一層夾襖步出監(jiān)牢的瞬間甚负,已是汗流浹背柬焕。 一陣腳步聲響...
    開(kāi)封第一講書(shū)人閱讀 31,987評(píng)論 1 266
  • 我被黑心中介騙來(lái)泰國(guó)打工, 沒(méi)想到剛下飛機(jī)就差點(diǎn)兒被人妖公主榨干…… 1. 我叫王不留梭域,地道東北人斑举。 一個(gè)月前我還...
    沈念sama閱讀 46,358評(píng)論 2 360
  • 正文 我出身青樓,卻偏偏與公主長(zhǎng)得像病涨,于是被迫代替她去往敵國(guó)和親富玷。 傳聞我的和親對(duì)象是個(gè)殘疾皇子,可洞房花燭夜當(dāng)晚...
    茶點(diǎn)故事閱讀 43,514評(píng)論 2 348

推薦閱讀更多精彩內(nèi)容