java中jvm的gc日誌解析,jvm如何查看gc日誌

本文目錄一覽：

• 1、理解CMS GC日誌
• 2、JVM GC 日誌詳解
• 3、jrockit的jvm的 gc日誌輸出能詳細到什麼程度
• 4、jvm GC日誌 相關參數
• 5、eclipse設置查看GC日誌和如何理解GC日誌
• 6、JVM性能調優（2） —— 內存設置和查看GC日誌

理解CMS GC日誌

本文以idea的啟動日誌為例解讀CMS收集器的GC日誌

在 idea64.exe.vmoptions 文件中可以看到idea的啟動參數，下面是初始啟動參數配置

其中 -XX:+UseConcMarkSweepGC 表示使用 ParNew + CMS + Serial Old 收集器組合進行內存回收，Serial收集器是作為CMS收集器出現Concurrent Model Failure失敗後的後備收集器，相當於替補。

接下來需要添加啟動參數來列印idea的GC日誌，JVM提供的幾個主要的GC日誌參數如下：

綜上，我們在 idea64.exe.vmoptions 文件中添加如下配置參數列印GC信息

然後重啟idea，就能在對應的D盤根目錄下找到生成的gc.log日誌。

由於日誌內容過長，一下子全展示出來太亂而不方便閱讀，這裡對日誌中每個不用的現象輸出分別做出講解。

首先文件的最開頭的信息如下：

這個很好理解，就是顯示了當前程序運行的環境，當前的jdk版本為1.8。

接下來的輸出信息如下：

這部分顯示了這次JVM的啟動參數配置，我們在idea64.exe.vmoptions配置的信息也會在這裡列印出來，我們可以從這裡看出很多默認配置，比如 -XX:MaxTenuringThreshold=6 這個參數，表示Survivor區的對象晉陞老年代的年齡閾值為6，這個值在JDK 1.8之前默認為15。

再下面就是應用的GC信息了，不同的內存區域（新生代和老年代）發生的GC日誌信息有所不同，下面一一舉例。

最前面的 2019-03-01T13:38:04.037+0800: 0.867: 是固定的， 2019-03-01T13:38:04.037+0800 表示GC發生的日期花間， 0.867 表示本次gc與JVM啟動時的相對時間，單位為秒。

[GC (Allocation Failure) 這裡的 GC 表示這是一次垃圾回收，但並不能單憑這個就判斷這是依次Minor GC，下文會說到CMS的標識為 [GC (CMS Initial Mark) 和 [GC (CMS Final Remark) ，同樣是 GC CMS的卻是是Major GC；括弧中的 Allocation Failure 表示gc的原因，新生代內存不足而導致新對象內存分配失敗。

再後面的 [ParNew: 表示本次gc使用的垃圾收集器為ParNew，我們知道ParNew是針對新生代的垃圾收集器，從這可以看出本次gc是Minor GC。後面緊跟著的 34944K-4352K(39296K) 的含義是 GC前該內存區域已使用容量 – GC後該內存區域已使用容量（該內存區域總容量） ，再後面的 0.0138186 secs 表示該內存區域GC所佔用的時間，單位為秒。

再後面的 34944K-6355K(126720K), 0.0141834 secs 表示收集前後整個堆的使用情況， 0.0141834 secs 表示本次GC的總耗時，包括把年輕代的對象轉移到老年代的時間。

最後的 [Times: user=0.06 sys=0.00, real=0.02 secs] 表示GC事件在不同維度的耗時，單位為秒。這裡面的user、sys和real與Linux的time命令所輸出的時間含義一致，分別表示用戶態消耗的CPU時間、內核態消耗的CPU時間和操作從開始到結束所經過的等待耗時，例如等待磁碟I/O、等待線程阻塞，而CPU時間不包括這些耗時，但當系統有多CPU或者多核的話，多線程操作會疊加這些CPU時間，所以有時候user或sys時間超過real時間也是完全正確的。

這裡先要明確Minor GC、Major GC和Full GC的區別：

老年代由CMS收集器執行的Major GC相對比較複雜，包括初始標記、並發標記、重新標記和並發清除4個階段，下面的gc日誌也詳細地描述了各個階段的信息。

為了更清晰的觀察各個階段的日誌信息，對上面的日誌信息重新排版並添加註釋，如下：

下面對上圖中各個階段的日誌進行分析

初始標記階段（CMS initial mark）

[GC (CMS Initial Mark) 表示這是CMS開始對老年代進行垃圾圾收集的初始標記階段，該階段從垃圾回收的「根對象」開始，且只掃描直接與「根對象」直接關聯的對象，並做標記，需要暫停用戶線程（Stop The Word，下面統稱為STW），速度很快。 104208K(126116K) 表示當前老年代的容量為126116K，在使用了104208K時開始進行CMS垃圾回收。可以計算下這個比例，104208 / 126116約等於0.83，可以大概推算出CMS收集器的啟動內存使用閾值。

後面的 108824K(165412K), 0.0055322 secs 表示當前整個堆的內存使用情況和本次初始標記耗費的時間，最後的 [Times: user=0.00 sys=0.00, real=0.00 secs] 上文已經講過，下文將不再重複。

並發標記階段（CMS concurrent mark）

該階段進行了細分，但都是和用戶線程並發進行的

[CMS-concurrent-mark 表示並發標記階段，會遍歷整個年老代並且標記活著的對象，後面的 0.154/0.155 secs 表示該階段持續的時間和時鐘時間，耗時0.15秒，可見耗時是比較長的。

由於該階運行的過程中用戶線程也在運行，這就可能會發生這樣的情況，已經被遍歷過的對象的引用被用戶線程改變，如果發生了這樣的情況，JVM就會標記這個區域為Dirty Card。

[CMS-concurrent-preclean 階段會把上一個階段被標記為Dirty Card的對象以及可達的對象重新遍歷標記，完成後清楚Dirty Card標記。另外，一些必要的清掃工作也會做，還會做一些final remark階段需要的準備工作。

[CMS-concurrent-abortable-preclean 並發預清理，這個階段嘗試著去承擔接下來STW的Final Remark階段足夠多的工作，由於這個階段是重複的做相同的事情直到發生aboart的條件（比如：重複的次數、多少量的工作、持續的時間等等）之一才會停止。這個階段很大程度的影響著即將來臨的Final Remark的停頓。

從後面的 1.190/1.707 secs 顯示這個階段持續了1秒多的時間，相當的長。

重新標記階段（CMS remark）

該階段同樣被細分為多個子階段

[GC (CMS Final Remark) 表示這是CMS的重新標記階段，會STW，該階段的任務是完成標記整個年老代的所有的存活對象，儘管先前的pre clean階段盡量應對處理了並發運行時用戶線程改變的對象應用的標記，但是不可能跟上對象改變的速度，只是為final remark階段盡量減少了負擔。

[YG occupancy: 24305 K (39296 K)] 表示年輕代當前的內存佔用情況，通常Final Remark階段要盡量運行在年輕代是足夠乾淨的時候，這樣可以消除緊接著的連續的幾個STW階段。

[Rescan (parallel) , 0.0103714 secs] 這是整個final remark階段掃描對象的用時總計，該階段會重新掃描CMS堆中剩餘的對象，重新從「根對象」開始掃描，並且也會處理對象關聯。本次掃描共耗時 0.0103714s。

[weak refs processing, 0.0006267 secs] 第一個子階段，表示對弱引用的處理耗時為0.0006267s。

[class unloading, 0.0368915 secs] 第二個子階段，表示卸載無用的類的耗時為0.0368915s。

[scrub symbol table, 0.0486196 secs] 最後一個子階段，表示清理分別包含類級元數據和內部化字元串的符號和字元串表的耗時。

[1 CMS-remark: 108093K(126116K)] 表示經歷了上面的階段後老年代的內存使用情況。再後面的 132398K(165412K), 0.1005635 secs 表示final remark後整個堆的內存使用情況和整個final remark的耗時。

並發清除階段（CMS concurrent sweep）

該階段和用戶線程並發執行，不會STW，作用是清除之前標記階段沒有被標記的無用對象並回收內存。整個過程分為兩個子階段。

CMS-concurrent-sweep 第一個子階段，任務是清除那些沒有標記的無用對象並回收內存。後面的參數是耗時，不再多提。

CMS-concurrent-reset 第二個子階段，作用是重新設置CMS演算法內部的數據結構，準備下一個CMS生命周期的使用。

這裡再講一個小知識點，我們上面提到CMS收集器會在老年代內存使用到一定程度時就觸發垃圾回收，這是因為CMS收集器的一個缺陷導致的這種設定，也就是無法處理「浮動垃圾」，「浮動垃圾」就是指標記清除階段用戶線程運行產生的垃圾，而這部分對象由於沒有做標記處理所以在本次CMS收集中是無法處理的。如果CMS是在老年代空間快用完時才啟動垃圾回收，那很可能會導致在並發階段由於用戶線程持續產生垃圾而導致老年代內存不夠用而導致「Concurrent Mode Failure」失敗，那這時候虛擬機就會啟用後備預案，臨時啟用Serial Old收集器來重新進行老年代的垃圾收集，Serial Old是基於「標記-整理」演算法的單線程收集器，這樣停頓時間就會很長。這個CMS啟動的內存使用閾值可以通過參數 -XX:CMSInitiatiingOccupancyFranction 來設置，默認為68%（這是網上查到的數據），不過這68%應該是JDK1.8之前版本的默認參數，因為上文中初始標記階段的gc日誌分析中顯示老年代內存使用到了83%才開始的CMS垃圾收集。我通過在命令行輸入 java -XX:+PrintFlagsInitial 命令查看到的本機參數如下，也不知道這-1是什麼意思，隨機？如果你知道，可以在文章下留言告知，十分感謝！

由於元空間內存不足而引發的Full GC

這裡還有一種Full GC日誌也比較容易出現，如下：

通過 [Full GC (Metadata GC Threshold) 我們知道這是一次針對整個堆（包括年輕代和老年代）的Full GC，括弧中的 Metadata GC Threshold 說明了gc發生的原因，是因為元空間內存不足夠而產生擴容導致的GC，同樣的我們還可以通過後面的 [CMS: 0K-19938K(1048576K) 看出在老年代內存使用為0的時候就發生了Full GC，所以可以確定不是因為老年代內存不夠用而發生的gc。

再後面的 [Metaspace: 20674K-20674K(1069056K)] 表示這次gc前後的元空間（Metaspace）內存變化，元空間的最大容量為1069056K，約等於1G，疑問便來了，最大容量為1G，已使用才20670K，為什麼會不夠用？

從JDK8開始，方法區採用元空間（Metaspace）的概念來實現，原來的永久代(PermGen)實現被廢棄。元空間並不在虛擬機中，而是使用本地內存，默認情況下，元空間的大小僅受本地內存限制。可以通過下面的參數來指定元空間的大小：

還有幾個參數也值得我們關註：

所以我們只要根據實際情況將元空間的初始值設置的大一點就可以避免這種Full GC。

程序中調用System.gc()而引發的Full GC

還有一種gc日誌，雖然不多見，但也在我這次啟動中出現了，如下

[Full GC (System.gc()) 說明這是一次Full GC，是由於調用System.gc()觸發的。

後面的 [CMS: 114245K-129265K(536576K) 表示這次gc後老年代內存佔用由114245K上漲到了 129265K ，注意，這並不能說明沒有對老年代進行回收；再後面的 378366K-129265K(997376K) 表示這次gc後整個堆空間大小縮小到了 129265K ，正好等於老年代的使用量，所以可以推斷這次Full GC回收了年輕代的內存，並將存活的對象全部移到了老年代。

為了更清楚的看清這次gc前後各個內存區域的內存佔用變化，在啟動參數中加入 -XX:+PrintHeapAtGC 參數列印GC前後的堆內存信息，重啟idea，同樣發生了這種gc，如下：

紅框部分的現象跟上面的現象差不多，紅框上面是gc前堆中各區域的使用情況，紅框下面是gc後堆中各區域的使用情況，可以看出這次gc後新生代確實被清空了（eden、form和to區使用量都為0%），老年代佔用內存變大，再反觀之前的由於元空間內存不足而發生的Full GC同樣也是清空了年輕代，由此可以推論出Full GC會對整個堆進行垃圾回收，並且會將年輕代存活的對象全部轉移到老年代。

本文章解讀了jdk1.8版本下idea採用CMS收集器時的啟動gc日誌信息，閱讀完這篇文章後能對GC日誌有個大體的認識，通過對GC日誌的分析可以幫助你更加清晰深入的理解JVM的內存分布，以及垃圾收集的具體細節。不同垃圾收集方案下的gc日誌會有所不同，但也都大同小異。

JVM GC 日誌詳解

本文採用的JDK版本：

設置JVM GC格式日誌的主要參數包括如下8個：

本文假設讀者已經熟悉JVM 內存結構。

如果想開啟GC日誌的信息，可以通過設置如下的參數任一參數：

如果只設置 -XX:+PrintGC 那麼列印的日誌如下所示：

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失敗的類型

3、 68896K-5080K 表示年輕代從68896K降為5080K

4、 256000K 表示整個堆的大小

5、 0.0041139 secs 表示這次GC總計所用的時間

在JDK 8中， -verbose:gc 是 -XX:+PrintGC 一個別稱，日誌格式等價與： -XX:+PrintGC ，。

不過在 JDK 9 中 -XX:+PrintGC被標記為 deprecated 。

-verbose:gc 是一個標準的選項， -XX:+PrintGC 是一個實驗的選項，建議使用 -verbose:gc 替代 -XX:+PrintGC

參考： Difference between -XX:+PrintGC and -verbose:gc

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失敗的類型

3、PSYoungGen 表示年輕代大小

4、 53248K-2176K 表示年輕代佔用從 53248K 降為 2176K

5、 59392K 表示年輕帶的大小

6、 58161K-7161K 表示整個堆佔用從 53248K 降為 2176K

7、 256000K 表示整個堆的大小

8、 0.0039189 secs 表示這次GC總計所用的時間

9、 [Times: user=0.02 sys=0.01, real=0.00 secs] 分別表示，用戶態佔用時長，內核用時，真實用時。

時間保留兩位小數，四捨五入。

如果加上 -XX:+PrintGCTimeStamps 那麼日誌僅僅比1.1介紹的最前面多了一個時間戳： 1.963 ， 表示從JVM啟動到列印GC時刻用了1.963秒。

如果加上 -XX:+PrintGCDateStamps 那麼日誌僅僅比1.1介紹的最前面多了一個日期時間： 2019-03-05T16:56:15.108+0800 ， 表示列印GC的時刻的時間是 2019-03-05T16:56:15.108+0800 。+0800表示是東8區。

這個參數開啟後，

使用如下參數 -verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M

列印日誌如下：

由此可以看出在，列印如下日誌前後

詳細列印出了日誌信息

invocations 表示GC的次數，每次GC增加一次，每次GC前後的invocations相等

1、 Heap before GC invocations=1 表示是第1次GC調用之前的堆內存狀況

2、 {Heap before GC invocations=1 (full 0): 表示是第1次GC調用之後的堆內存狀況

如果使用該參數 -Xloggc 則默認開啟如下兩個參數

如果啟動參數如下： -Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M 則日誌格式如下所示

gc.log 也可以指定絕對的路徑。

在gc.log最前面還會默認列印系統的JDK版本與啟動的參數

此設置 -XX:+PrintReferenceGC可以列印出SoftReference，WeakReference，FinalReference，PhantomReference，JNI Weak Reference幾種引用的數量，以及清理所用的時長，該參數在進行YGC調優時可以排上用場。

具體可以參考佔小狼的一篇實戰： 一次 Young GC 的優化實踐（FinalReference 相關）

CMS日誌分為兩個STW(stop the world)

分別是 init remark （1） 與 remark （7）兩個階段。一般耗時比YGC長約10倍（個人經驗）。

（1）、 [GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

會STO(Stop The World)，這時候的老年代容量為 32768K， 在使用到 19498K 時開始初始化標記。耗時短。

（2）、 [CMS-concurrent-mark-start]

並發標記階段開始

（3）、 [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

並發標記階段花費時間。

（4）、 [CMS-concurrent-preclean-start]

並發預清理階段，也是與用戶線程並發執行。虛擬機查找在執行並發標記階段新進入老年代的對象(可能會有一些對象從 新生代 晉陞到老年代， 或者有一些對象被分配到老年代)。通過重新掃描，減少下一個階段」重新標記」的工作，因為下一個階段會Stop The World。

（5）、 [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

並發預清理階段花費時間。

（6）、 [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

並發可中止預清理階段，運行在並行預清理和重新標記之間，直到獲得所期望的eden空間佔用率。增加這個階段是為了避免在重新標記階段後緊跟著發生一次垃圾清除

（7）、 [GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

會STW(Stop The World)，收集階段，這個階段會標記老年代全部的存活對象，包括那些在並發標記階段更改的或者新創建的引用對象

（8）、 [CMS-concurrent-sweep-start]

並發清理階段開始，與用戶線程並發執行。

（9）、 [CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

並發清理階段結束，所用的時間。

（10）、 [CMS-concurrent-reset-start]

開始並發重置。在這個階段，與CMS相關數據結構被重新初始化，這樣下一個周期可以正常進行。

（11）、 [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

並發重置所用結束，所用的時間。

參考：

Geek-Yan : JVM 學習筆記(四) CMS GC日誌詳解

設置JVM GC 性能的有如下參數

新生代大小官網推薦的大小是 3/8 , 如果設置太小，比如 1/10會 導致 Minor GC 與 Major GC 次數增多。

其中n的大小為區間為[0,15],如果高於15，JDK7 會默認15，JDK 8會啟動報錯

發生在CMS GC運行期間，詳情參考：

JVM 調優 —— GC 長時間停頓問題及解決方法

GC的悲觀策略

發生在Minor GC期間

jrockit的jvm的 gc日誌輸出能詳細到什麼程度

可以通過在java命令種加入參數來指定對應的gc類型，列印gc日誌信息並輸出至文件等策略。

GC的日誌是以替換的方式()寫入的，而不是追加()，如果下次寫入到同一個文件中的話，以前的GC內容會被清空。

對應的參數列表

-XX:+PrintGC 輸出GC日誌

-XX:+PrintGCDetails 輸出GC的詳細日誌

-XX:+PrintGCTimeStamps 輸出GC的時間戳（以基準時間的形式）

-XX:+PrintGCDateStamps 輸出GC的時間戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在進行GC的前後列印出堆的信息

-Xloggc:../logs/gc.log 日誌文件的輸出路徑

這裡使用如下的參數來進行日誌的列印：

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs

對於新生代回收的一行日誌，其基本內容如下：

2014-07-18T16:02:17.606+0800: 611.633: [GC 611.633: [DefNew: 843458K-2K(948864K), 0.0059180 secs] 2186589K-1343132K(3057292K), 0.0059490 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

其含義大概如下：

2014-07-18T16:02:17.606+0800（當前時間戳）: 611.633（時間戳）: [GC（表示Young GC） 611.633: [DefNew（單線程Serial年輕代GC）: 843458K（年輕代垃圾回收前的大小）-2K（年輕代回收後的大小）(948864K（年輕代總大小）), 0.0059180 secs（本次回收的時間）] 2186589K（整個堆回收前的大小）-1343132K（整個堆回收後的大小）(3057292K（堆總大小）), 0.0059490 secs（回收時間）] [Times: user=0.00（用戶耗時） sys=0.00（系統耗時）, real=0.00 secs（實際耗時）]

老年代回收的日誌如下：

2014-07-18T16:19:16.794+0800: 1630.821: [GC 1630.821: [DefNew: 1005567K-111679K(1005568K), 0.9152360 secs]1631.736: [Tenured:

2573912K-1340650K(2574068K), 1.8511050 secs] 3122548K-1340650K(3579636K), [Perm : 17882K-17882K(21248K)], 2.7854350 secs] [Times: user=2.57 sys=0.22, real=2.79 secs]

gc日誌中的最後貌似是系統運行完成前的快照：

Heap

def new generation total 1005568K, used 111158K [0x00000006fae00000, 0x000000073f110000, 0x0000000750350000)

eden space 893888K, 12% used [0x00000006fae00000, 0x0000000701710e90, 0x00000007316f0000)

from space 111680K, 3% used [0x0000000738400000, 0x000000073877c9b0, 0x000000073f110000)

to space 111680K, 0% used [0x00000007316f0000, 0x00000007316f0000, 0x0000000738400000)

tenured generation total 2234420K, used 1347671K [0x0000000750350000, 0x00000007d895d000, 0x00000007fae00000)

the space 2234420K, 60% used [0x0000000750350000, 0x00000007a2765cb8, 0x00000007a2765e00, 0x00000007d895d000)

compacting perm gen total 21248K, used 17994K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)

the space 21248K, 84% used [0x00000007fae00000, 0x00000007fbf92a50, 0x00000007fbf92c00, 0x00000007fc2c0000)

No shared spaces configured.

jvm GC日誌 相關參數

-XX:+PrintGC 最簡單的 GC 參數 會列印 GC 前後堆空間使用情況以及 GC 花費的時間

-XX:+PrintGCDetaill 會列印 youngGC FullGC前後堆【新生代，老年代，永久區】的使用情況以及 GC 時用戶態 CPU 耗時及系統 CPU 耗時及 GC 實際經歷的時間

-XX:+PrintGCHeapAtGC 比-XX:+PrintGCDetaill更全面的堆信息

-XX:+PrintGCTimeStamps 輸出發生 GC 的時間，輸出時間為虛擬機啟動後的時間偏移量

-XX:+PrintGCApplicationConcurrentTime 列印應用程序執行的時間

-XX:+PrintGCApplicationStoppedTime 列印應用程序由於 GC 停頓的時間

-XX:+PrintReferenceGC 列印系統中軟引用 弱引用 虛引用

-Xloggc : log/gc.log 指定 gc 日誌輸出位置

eclipse設置查看GC日誌和如何理解GC日誌

1. Run as – Run configurations – java應用名 – arguments -VM arguments，加入jvm參數就行

2. 測試代碼

[java] view plain copy

package cn.erong.test;

public class Jtest {

private static final int _1M = 1024*1024;

public static void main(String[] args) {

byte[] allocation1,allocation2,allocation3,allocation4;

allocation1 = new byte[_1M/4];

allocation2 = new byte[_1M/4];

allocation3 = new byte[4*_1M];

allocation4 = new byte[4*_1M];

allocation4 = null;

allocation4 = new byte[4*_1M];

}

}

3.  測試看下，在vm arguments 中加入

[java] view plain copy

-Xms20m –jvm堆的最小值

-Xmx20m –jvm堆的最大值

-XX:+PrintGCTimeStamps — 列印出GC的時間信息

-XX:+PrintGCDetails  –列印出GC的詳細信息

-verbose:gc –開啟gc日誌

-Xloggc:d:/gc.log — gc日誌的存放位置

-Xmn10M — 新生代內存區域的大小

-XX:SurvivorRatio=8 –新生代內存區域中Eden和Survivor的比例

4 . run  看下日誌，到d盤找到 gc.log，如下

[plain] view plain copy

Java HotSpot(TM) Client VM (25.151-b12) for windows-x86 JRE (1.8.0_151-b12), built on Sep  5 2017 19:31:49 by “java_re” with MS VC++ 10.0 (VS2010)

Memory: 4k page, physical 3567372k(982296k free), swap 7133056k(3042564k free)

CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:-UseLargePagesIndividualAllocation

0.091: [GC (Allocation Failure) 0.091: [DefNew: 5427K-995K(9216K), 0.0036445 secs] 5427K-5091K(19456K), 0.0038098 secs] [Times: user=0.00 sys=0.02, real=0.00 secs]

0.095: [GC (Allocation Failure) 0.095: [DefNew: 5091K-0K(9216K), 0.0012412 secs] 9187K-5090K(19456K), 0.0012908 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

Heap

def new generation   total 9216K, used 4260K [0x04000000, 0x04a00000, 0x04a00000)

eden space 8192K,  52% used [0x04000000, 0x044290e8, 0x04800000)

from space 1024K,   0% used [0x04800000, 0x04800000, 0x04900000)

to   space 1024K,   0% used [0x04900000, 0x04900000, 0x04a00000)

tenured generation   total 10240K, used 5090K [0x04a00000, 0x05400000, 0x05400000)

the space 10240K,  49% used [0x04a00000, 0x04ef8ac0, 0x04ef8c00, 0x05400000)

Metaspace       used 84K, capacity 2242K, committed 2368K, reserved 4480K

JVM性能調優（2） —— 內存設置和查看GC日誌

1）JVM內存分配有如下一些參數：

一般 -Xms 和 -Xmx 設置一樣的大小，-XX:MetaspaceSize 和 -XX:MaxMetaspaceSize 設置一樣的大小。-Xms 等價於 -XX:InitialHeapSize，-Xmx等價於-XX:MaxHeapSize；-Xmn等價於-XX:MaxNewSize。

2）在IDEA中可以按照如下方式設置JVM參數：

3）命令行啟動時可以按照如下格式設置：

1）設置GC參數：

可以在啟動時加上如下參數來查看GC日誌：

例如，我在IDEA中添加了如下JVM啟動參數：

啟動程序之後列印出了如下的一些日誌：

從第三行 CommandLine flags 可以得到如下的信息：

2）查看默認參數：

如果要查看JVM的默認參數，就可以通過給JVM加列印GC日誌的參數，就可以在GC日誌中看到JVM的默認參數了。

還可以在啟動參數中添加 -XX:+PrintFlagsFinal 參數，將會列印系統的所有參數，就可以看到自己配置的參數或系統的默認參數了：

3）GC日誌：

之後的日誌就是每次垃圾回收時產生的日誌，每行日誌說明了這次GC的執行情況，例如第四行GC日誌：

詳細內容如下：

2020-09-25T13:00:41.631+0800：GC發生的時間點。

4.013：系統運行多久之後發生的GC，單位秒，這裡就是系統運行 4.013 秒後發生了一次GC。

GC (Allocation Failure)：說明了觸發GC的原因，這裡是指對象分配失敗導致的GC。

PSYoungGen：指觸發的是年輕代的垃圾回收，使用的是 Parallel Scavenge 垃圾回收器。

419840K-20541K：對年輕代執行了一次GC，GC之前年輕代使用了 419840K，GC之後有 20541K 的對象活下來了。

(472064K)：年輕代可用空間是 472064K，即 461 M，為什麼是461M呢？因為新生代大小為 512M，Eden 區占 409.6M，兩塊 Survivor 區各占 51.2M，所以年輕代的可用空間為 Eden+1個Survivor的大小，即460.8M，約為461M。

419840K-20573K：GC前整個堆內存使用了 419840K，GC之後堆內存使用了 20573K。

(996352K)：整個堆的大小是 996352K，即 973M，其實就是年輕代的 461M + 老年代的 512 M

0.0118345 secs：本次GC耗費的時間

Times: user=0.00 sys=0.00, real=0.01 secs：本次GC耗費的時間

4）JVM退出時的GC情況：

程序結束運行後，還會列印一些日誌，就是第12行之後的日誌，這部分展示的是當前堆內存的使用情況：

詳細內容如下：