天天看點
傳回

gc日志怎麼看_手撕 JVM 垃圾收集日志

gc日志怎麼看_手撕 JVM 垃圾收集日志

下圖是本篇的寫作大綱，将從以下四個方面介紹怎麼樣處理 JVM 日志。

gc日志怎麼看_手撕 JVM 垃圾收集日志
有準備才能不慌

想要分析日志，首先你得有日志呀，對不對。凡是未雨綢蒙總是沒錯的。所謂有日志的意思，你要把 JVM 參數配置好，日志格式、日志存儲位置等參數，當然了，除了日志相關參數外，其他的一些必要參數最好也配置上，比如 HeapDump 。

我相信大部分成熟的項目都會配置 JVM 參數。但是還是有一些小項目真的會忽略。以至于 JVM 崩潰的時候不友善查找問題原因而追悔莫及。比如下面這位同學（純屬虛構），雖然對話是虛構，但是是真的有不配置參數的。

gc日志怎麼看_手撕 JVM 垃圾收集日志
要配置，有防備，不後悔；不配置，不準備，會追悔。 
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-Xloggc:/Users/fengzheng/jvmlog/gc.log
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/Users/fengzheng/jvmlog

以上可以說是配置 JVM 日志以及 dump 現場最基本的配置了。這裡隻介紹關于日志的參數，其他的參數可以讀一下 JVM 你不可不知的參數

加了以上配置的 JVM 就像是一台裝有

黑匣子

的飛機。

一個重要概念

并發(Concurrent)和并行(Parallel)在 JVM 垃圾收集過程中的定義有很多同學搞不清楚。是以沒次讀到這兩個概念的時候都一頭霧水。

并發(Concurrent)

：指垃圾收集線程和使用者線程可以同時進行。也就是說 JVM 在進行垃圾收集的時候，使用者還是可以正常的使用應用系統提供的服務。(當然了，并沒有一種完全并發的垃圾收集器，隻是說在垃圾收集的大部分階段是并發的)

并行(Parallel)

：指垃圾收集器是多線程工作的，比方說有4個線程同時進行垃圾收集的工作，但是在收集的過程中，使用者線程是被挂起的。也就是在進行并行收集的時候，使用者無法正常使用應用系統提供的服務。

分析背景

本篇的全部内容都基于 JDK 8 Hotspot JVM，分别從 ParallelGC 、CMS、G1 三種常用的垃圾收集器來分析。可以通過下圖檢視三種垃圾收集器的對應關系，分别對應圖中标示的 1、2、3。

gc日志怎麼看_手撕 JVM 垃圾收集日志

為了友善日志分析，我設定了一下簡單的 JVM 作為基礎參數，其中年輕代 10M，老年代 10M，堆大小 20M。

-Xms20M
-Xmx20M
-Xmn10M
-XX:SurvivorRatio=8
-XX:MetaspaceSize=6M
-XX:MaxMetaspaceSize=6M
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/Users/fengzheng/jvmlog
簡單日志格式

通過參數

-verbose:gc 或者 -XX:+PrintGC

可以讓 JVM 開啟簡單日志格式，對于這幾種垃圾收集期，簡單日志的格式都是一緻的。簡單日志内容很少，隻有GC類型(标示是 Minor GC 還是 Full GC)、GC 原因、堆收集前和收集後大小、堆的總大小以及收集耗時。

下面是簡單日志配置下的幾條收集日志，包括正常的空間配置設定失敗引起的收集、System.gc() 觸發的垃圾收集、以及執行 jmap -histo:live pid 指令執行的垃圾收集。

# Minor GC 新生代 GC
[GC (Allocation Failure)  7164K->704K(19456K), 0.0017002 secs]

# System.gc() 觸發 Full GC
[GC (System.gc())  4157K->648K(19456K), 0.0019522 secs]
[Full GC (System.gc())  648K->609K(19456K), 0.0099904 secs]

# jmap -histo:live 觸發 Full GC
[GC (Heap Inspection Initiated GC)  938K->737K(19456K), 0.0009119 secs]
[Full GC (Heap Inspection Initiated GC)  737K->573K(19456K), 0.0070892 secs]

下圖說明了一條簡單格式的垃圾收集日志各個字段的含義。

gc日志怎麼看_手撕 JVM 垃圾收集日志

在實際的生産環境中，隻用簡單格式的 JVM 日志意義不大，得到的有用資訊不多，也就是知道垃圾收集次數、收集耗時以及堆的使用量，對于排查分析問題的幫助不是很大，是以，一般都會配置更加詳細的日志格式。

詳細日志格式

使用

-XX:+PrintGCDetails

和

-XX:+PrintGCDateStamps

這兩個參數可以列印詳細的垃圾收集日志和垃圾收集的時間戳。當然了，除了這兩個之外，還有一些更具體的參數，比如收集前後列印堆使用資訊的

-XX:+PrintHeapAtGC

參數等等。

當然了，參數配置的越多，列印的資訊越是詳細，對于排查問題越有幫助，就是内容就會變得很多，肉眼看起來會比較抓狂。

Parallel Scavenge 收集器

在 JDK 8 中，如果不指定垃圾收集器，預設是使用參數

-XX:+UseParallelGC

的，也就是新生代使用 Parallel Scavenge，老年代配合使用的是

Serial Old

。

Parallel Scavenge

是一款并行的、高吞吐量的垃圾收集器，采用複制算法。适用于追求高效率的、對即時響應要求不高的系統。

要了解清楚 GC 日志各部分的含義，就要了解 JVM 記憶體模型以及垃圾收集器對于記憶體的規劃和管理情況，老樣子，還是通過圖來看一下比較清楚。JDK 8 支援的除 G1 外的垃圾收集器，都适用此圖，包括下面要介紹的 CMS。

gc日志怎麼看_手撕 JVM 垃圾收集日志

垃圾收集的部分即是上圖中的「

方法區

」和 「

堆

」兩部分。收集日志也基本上是描述這兩部分的大小和變化情況。

在上面的背景介紹中給出了本次測試所用的參數。年輕代 10M ，老年代 10M，Metaspace 區 6M。下圖是堆空間記憶體分布圖，年輕代分為 Eden區和 S0、S1 兩個區，SurvivorRatio為8，這也是預設值，表示新生代 Eden 占年輕代總大小的 80%，也就是 10*80%=8M，而 S0、S1 各占10%，也就是 1M。

gc日志怎麼看_手撕 JVM 垃圾收集日志

好了，基于上面的基礎認識。開始分析垃圾收集日志，以下是兩條日志，第一條是一次 Minor GC，第二條是 Full GC。

2019-12-03T16:20:47.980-0800: [GC (System.gc()) [PSYoungGen: 4068K->656K(9216K)] 4076K->672K(19456K), 0.0016106 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-12-03T16:20:47.982-0800: [Full GC (System.gc()) 
            [PSYoungGen: 656K->0K(9216K)],
        [ParOldGen: 16K->570K(10240K)] 672K->570K(19456K), 
        [Metaspace: 3910K->3910K(1056768K)],
 0.0110117 secs] 
 [Times: user=0.02 sys=0.00, real=0.01 secs]

為了更清楚的說明各個部分的含義，我居然又畫了一張圖（PS:畫個圖真是不容易），看一下各部分代表的含義。

gc日志怎麼看_手撕 JVM 垃圾收集日志

上圖示注的是一條 Full GC 日志，Full GC 同時收集了年輕代、老年代以及 metaspace 區。Full GC 日志包含了 Minor GC 的内容，那我們就直接分析 Full GC 了。

時間戳

：日志以時間戳作為開端，表示此次垃圾收集發生的時間，由

-XX:+PrintGCDateStamps

參數決定是否開啟。

收集内容主體

：

沿着日志順序往後看，

Full GC (System.gc())

，收集類型(是 Full GC 還是 Minor GC) ，括号裡跟着發生此次垃圾收集的原因。

再後面是年輕代、老年代、Metaspace 區詳細的收集情況。

[PSYoungGen: 656K->0K(9216K)]

，翻譯為 「年輕代：年輕代收集前記憶體使用量->年輕代垃圾收集後記憶體使用量（年輕代可用記憶體總大小）」，垃圾收集前年輕代已使用 656K，垃圾收集後已使用 0K，說明被回收了 656K，總可用大小為 9216K(9M)。诶，不對呀？怎麼是 9M 呢，年輕代不是分了 10 M 嗎。因為可用記憶體和總記憶體不能劃等号，S0 和 S1 隻能有一塊被算進可用記憶體，是以可用記憶體為 Eden + S0/S1=9M。

[ParOldGen: 16K->570K(10240K)] 672K->570K(19456K)

，翻譯為 「[老年代：老年代收集前記憶體使用量->老年代垃圾收集後記憶體使用量（老年代可用記憶體總大小）] 堆空間（包括年輕代和老年代）垃圾收集前記憶體使用量->堆空間垃圾收集後記憶體使用量（堆空間總可用大小）」。

垃圾收集前老年使用 16K，收集後呢，竟然變大了，确定沒有看錯嗎。是的，沒有。這是因為年輕代的對象有一些進入了老年代導緻的。老年代 16K 變成了 570K，說明有 554K 是年輕代晉升而來的。而記憶體總大小由 672K 減少到了 570K，說明有102K的記憶體真正的被清理了。

[Metaspace: 3910K->3910K(1056768K)]

翻譯為元空間回收前大小為 3910K，回收後大小為3910K，總可用大小為 1056768K。我們不是設定的 6M 嗎，怎麼這麼大，沒起作用嗎。實際上這個值是

CompressedClassSpaceSize +(2*InitialBootClassLoaderMetaspaceSize)

的大小，我們隻設定了 MaxMetaspaceSize ，并沒有設定這兩個參數。使用如下指令可以看到這兩個值的預設大小

jinfo -flag CompressedClassSpaceSize 75867
-XX:CompressedClassSpaceSize=1073741824
jinfo -flag InitialBootClassLoaderMetaspaceSize 75867
-XX:InitialBootClassLoaderMetaspaceSize=4194304

機關是 byte，CompressedClassSpaceSize 的值是 1048576K(其實就是1G，預設值)，InitialBootClassLoaderMetaspaceSize的值是 4M，用上面的公式計算，正好是 1056768K(1032M)

耗時統計

[Times: user=0.02 sys=0.00, real=0.01 secs]

user=0.02 表示執行使用者态代碼的耗時，這裡也就是 GC 線程消耗的 CPU 時間。如果是多線程收集器，這個值會高于 real 時間。

sys=0.00 表示執行核心态代碼的耗時。

real=0.01 表示應用停頓時長，多線程垃圾收集情況下，此數值應該接近(user + sys) / GCThreads（收集線程數），即單核上的平均停頓時間。

CMS 收集器

CMS 是一款老年代垃圾收集器，年輕代使用 ParNew 與之配合使用。它是一款并發、低停頓的垃圾收集器。适用于要求低延遲、即時響應的應用系統。

CMS 規劃的記憶體模型和上面 Parallel Scavenge 的是一緻的，可以參考上面的記憶體分布圖。

CMS

采用

标記-清除

算法，算法過程比較複雜，分為一下幾個步驟：

  • 初始标記（CMS initial mark），會導緻 stop the world；
  • 并發标記（CMS concurrent mark），與使用者線程同時運作；
  • 預清理（CMS-concurrent-preclean），與使用者線程同時運作；
  • 可被終止的預清理（CMS-concurrent-abortable-preclean） 與使用者線程同時運作；
  • 重新标記（CMS remark），會導緻 stop the world；
  • 并發清除（CMS concurrent sweep），與使用者線程同時運作；
  • 并發重置狀态等待下次CMS的觸發(CMS-concurrent-reset)，與使用者線程同時運作；

隻有初始标記和重新标記這兩個步驟會導緻 STW，但是這兩個步驟耗時很短，其他步驟可以與使用者線程同時運作，是以使用者幾乎感覺不到 JVM 停頓。

使用參數

-XX:+UseConcMarkSweepGC

可啟用 CMS 垃圾收集器。更詳細的參數如下：

-XX:+UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction=70
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
-XX:+CMSClassUnloadingEnabled
-XX:+ParallelRefProcEnabled
# 在重新标記之前對年輕代做一次minor GC
-XX:+CMSScavengeBeforeRemark

使用了

-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses

或

-XX:+ExplicitGCInvokesConcurrent

參數，在進行 Full GC 的時候，比如執行 System.gc() 操作，會觸發 CMS GC，以此來提高 GC 效率。

以下是啟用 CMS 後摘的一段 GC 日志，由于内容過長，下面我就直接在日志上做注釋了。

# System.gc() 觸發一次 Full GC
# -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses 參數
# 導緻Full GC 以 CMS GC 方式執行
# 先由 ParNew 收集器回收年輕代
2019-12-03T16:43:03.179-0800: [GC (System.gc()) 2019-12-03T16:43:03.179-0800: [ParNew: 3988K->267K(9216K), 0.0091869 secs] 3988K->919K(19456K), 0.0092257 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

# 初始标記階段，标記那些直接被 GC root 引用或者被年輕代存活對象所引用的所有對象
# 老年代目前使用 651K
# 老年代可用大小 10240K=10M
# 目前堆記憶體使用量 919K
# 目前堆可用記憶體 19456K=19M
# “1 CMS-initial-mark” 這裡的 1 表示老生代
2019-12-03T16:43:03.189-0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 651K(10240K)] 919K(19456K), 0.0002156 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

# 并發标記開始
# 标記所有存活的對象，它會根據上個階段找到的 GC Roots 周遊查找
2019-12-03T16:43:03.189-0800: [CMS-concurrent-mark-start]

# 并發标記階段耗時統計
2019-12-03T16:43:03.190-0800: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

# 并發預清理階段開始
# 在上述并發标記過程中，一些對象的引用可能會發生變化，JVM 會将包含這個對象的區域（Card）标記為 Dirty
# 在此階段，能夠從 Dirty 對象到達的對象也會被标記，這個标記做完之後，dirty card 标記就會被清除了
2019-12-03T16:43:03.190-0800: [CMS-concurrent-preclean-start]

# 并發預清理耗時統計
2019-12-03T16:43:03.190-0800: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

# 重新标記階段，目的是完成老年代中所有存活對象的标記
# 上一階段是并發執行的，在執行過程中對象的引用關系還會發生變化，是以再次标記
# 因為配置了 -XX:+CMSScavengeBeforeRemark 參數，是以會在标記發生一次 Minor GC
# 進行一次Minor GC,完成後年輕代可用空間 267K，年輕代總大小9216K
2019-12-03T16:43:03.190-0800: [GC (CMS Final Remark) [YG occupancy: 267 K (9216 K)]
# 更詳細的年輕代收集情況
2019-12-03T16:43:03.190-0800: [GC (CMS Final Remark) 2019-12-03T16:43:03.190-0800: [ParNew: 267K->103K(9216K), 0.0021800 secs] 919K->755K(19456K), 0.0022127 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
# 在程式暫停時重新進行掃描(Rescan),以完成存活對象的标記
2019-12-03T16:43:03.192-0800: [Rescan (parallel) , 0.0002866 secs]
# 第一子階段：處理弱引用
2019-12-03T16:43:03.193-0800: [weak refs processing, 0.0015605 secs]
# 第二子階段：解除安裝不适用的類
2019-12-03T16:43:03.194-0800: [class unloading, 0.0010847 secs]
# 第三子階段:清理持有class級别 metadata 的符号表(symbol tables),以及内部化字元串對應的 string tables
# 完成後老年代使用量為651K(老年代總大小10240K=10M)
# 整個堆使用量 755K(總堆大小19456K=19M)
2019-12-03T16:43:03.195-0800: [scrub symbol table, 0.0015690 secs]
2019-12-03T16:43:03.197-0800: [scrub string table, 0.0003786 secs][1 CMS-remark: 651K(10240K)] 755K(19456K), 0.0075058 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]

#開始并發清理 清除未被标記、不再使用的對象以釋放記憶體空間
2019-12-03T16:43:03.198-0800: [CMS-concurrent-sweep-start]
#并發清理階段耗時
2019-12-03T16:43:03.198-0800: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

# 開始并發重置，重置CMS算法相關的内部資料, 為下一次GC循環做準備
2019-12-03T16:43:03.198-0800: [CMS-concurrent-reset-start]
# 重置耗時
2019-12-03T16:43:03.199-0800: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

# 下面是執行 jmap -histo:live 指令觸發的 Full GC
# GC 類型是 Full GC
# 觸發原因是 Heap Inspection Initiated GC
# CMS收集老年代：從清理前的650K變為清理後的617K，總的老年代10M,耗時0.0048490秒
# 總堆使用大小由 1245K變為617K，總堆19M
# metaspace: 3912K變為3912K，
# metaspace 總大小顯示為  CompressedClassSpaceSize +(2*InitialBootClassLoaderMetaspaceSize)
2019-12-03T16:43:20.115-0800: [Full GC (Heap Inspection Initiated GC) 2019-12-03T16:43:20.115-0800: [CMS: 650K->617K(10240K), 0.0048490 secs] 1245K->617K(19456K), [Metaspace: 3912K->3912K(1056768K)], 0.0049050 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

以上就是對 CMS 垃圾收集器産生日志的分析，因為過程複雜，是以産生的日志内容也比較多。

G1 收集器

G1 收集器是在 JDK 7 版本中就已經正式推出，并且作為 JDK 9 預設的垃圾收集器。

Parallel Scavenge

：我追求高吞吐量，現在社會什麼最重要，效率呀，有沒有。

CMS

：效率固然重要，極緻的使用者體驗才是王道啊，不能讓使用者等啊，不能等啊，低停頓、即時響應是我畢生追求。

G1（一臉不屑）

：有句話不隻當講不當講，首先聲明沒有惡意，我想說，在座的各位都是垃圾。上面兩位說的，我全都有，是的，全都有。 (ps：結果被打)

以上純屬開個玩笑，隻是為了說明 G1 在滿足了低停頓的同時也保證了高吞吐量，适用于多核處理器、大記憶體容量的服務端系統。

G1

是 CMS 的替代版本，具有如下特點：

  • 橫跨年輕代和老年代，不需要其他收集器配合；
  • 并發收集器，可以與使用者線程并發執行；
  • 會壓縮記憶體碎片；
  • 可預測的停頓時間與高吞吐量；

與其他的垃圾收集器不同，G1 對堆記憶體做了不一樣的規劃，雖然還是使用分代政策，分為老年代、年輕代，年輕代又分為 Eden、Survivior 區，但是隻是邏輯劃分，實體上并不連續。它是将堆記憶體分為一系列大小在1M-32M 不等的 Region 區，通過下方的圖可以直覺的看出效果。

gc日志怎麼看_手撕 JVM 垃圾收集日志

G1 垃圾收集包括年輕代收集和老年代收集兩部分。 年輕代比較簡單，收集器如果檢測到存活區對象存活時間達到門檻值，就會将這些存活對象轉移到新的 Survivor 區或老年代，此過程會導緻 stop the world。 老年代的收集就比較複雜了，包括如下幾個階段： - 初始标記階段(Initial Marking Phase)，會導緻 stop the wrold; - 根區域掃描（Root Region Scan），與應用程式并發執行； - 根區域掃描（Root Region Scan），與應用程式并發執行； - 并發标記（Concurrent Marking），與應用程式并發執行； - 最終标記（Remark），會導緻 stop the wrold; - 複制/清除（Copying/Cleanup），會導緻 stop the wrold;

開啟 G1 收集器的參數如下：

-XX:+UseG1GC
-XX:MaxGCPauseMillis=100

使用 G1 收集器時，一般不設定年輕代的大小。

以下是一次 G1 收集的日志，簡單的分析直接寫到下面的日志内了。

# 進行了一次年輕代 GC,耗時0.0008029S
[GC pause (G1 Humongous Allocation) (young), 0.0008029 secs]
# 4個GC線程并行執行
   [Parallel Time: 0.5 ms, GC Workers: 4]
   # GC 線程耗時統計，反應收集的穩定性和效率
      [GC Worker Start (ms): Min: 90438.1, Avg: 90438.2, Max: 90438.4, Diff: 0.3]
      # 掃描堆外記憶體耗時統計
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.6]
      # 更新和掃描RSets 耗時統計
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 0.2, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      #掃描堆中的 root 對象耗時統計
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # 拷貝存活對象耗時統計
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      # GC 線程確定自身安全停止耗時統計
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # GC的worker 線程的工作時間總計
      [GC Worker Total (ms): Min: 0.1, Avg: 0.4, Max: 0.5, Diff: 0.3, Sum: 1.5]
      # GC的worker 線程完成作業的時間統計
      [GC Worker End (ms): Min: 90438.6, Avg: 90438.6, Max: 90438.6, Diff: 0.0]
   # 修複GC期間code root指針改變的耗時
   [Code Root Fixup: 0.0 ms]
   # 清除code root耗時
   [Code Root Purge: 0.0 ms]
   # 清除card tables 中的dirty card的耗時
   [Clear CT: 0.0 ms]
   # 其他方面比如選擇CSet、處理已用對象、引用入ReferenceQueues、釋放CSet中的region等的耗時
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.0 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   # 收集前 Eden區使用量 1024K(總容量9216K),收集後容量0B(總容量9216K)
   # Survivors 區收集前後的大小
   # 堆空間收集前使用量13.4M(總量20M),收集後650.2K
   [Eden: 1024.0K(9216.0K)->0.0B(9216.0K) Survivors: 1024.0K->1024.0K Heap: 13.4M(20.0M)->650.2K(20.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

# 初始标記階段，耗時0.0031800s
2019-12-03T16:48:25.456-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0031800 secs][Parallel Time: 2.5 ms, GC Workers: 4]
      [GC Worker Start (ms): Min: 4115.2, Avg: 4115.4, Max: 4115.8, Diff: 0.6]
      ...
   [Eden: 3072.0K(10.0M)->0.0B(9216.0K) Survivors: 0.0B->1024.0K Heap: 9216.0K(20.0M)->744.0K(20.0M)]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 

# Root區掃描 
2019-12-03T16:48:25.460-0800: [GC concurrent-root-region-scan-start]
2019-12-03T16:48:25.462-0800: [GC concurrent-root-region-scan-end, 0.0024198 secs]
# 并發标記
2019-12-03T16:48:25.462-0800: [GC concurrent-mark-start]
2019-12-03T16:48:25.462-0800: [GC concurrent-mark-end, 0.0001306 secs]

# 再次标記
2019-12-03T16:48:25.462-0800: [GC remark 2019-12-03T16:48:25.462-0800: [Finalize Marking, 0.0015922 secs] 2019-12-03T16:48:25.464-0800: [GC ref-proc, 0.0004899 secs] 2019-12-03T16:48:25.465-0800: [Unloading, 0.0016093 secs], 0.0040544 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
# 清理工作 
2019-12-03T16:48:25.467-0800: [GC cleanup 4000K->4000K(20M), 0.0003710 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs]
其他工具

大多數時候靠肉眼分析日志是很困難的，借助一些分析工具是必不可少的。

線上日志分析網站：https://gceasy.io/

線上 JVM 參數生成：https://opts.console.perfma.com/result/generate/JlKEV

還可以讀：

JVM 你不可不知的參數

無意中就做了個 web 版 JVM 監控端

JConsole、VisualVM 依賴的 JMX 技術

Java 調試工具、熱部署、JVM 監控工具都用到了它

我們說的 JVM 記憶體是什麼

分析 JVM 常用的 JDK 内置工具

gc日志怎麼看 jvm記憶體參數配置
上一篇: JVM 垃圾回收，了解GC日志
下一篇: 了解GC日志了解GC日志

繼續閱讀