手撕 JVM 垃圾收集日志

本文轉載自查看原文 2019-12-13 09:10 543 JVM/ java/ CMS/ 垃圾收集日志/ G1/ GC

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

有准備才能不慌

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

我相信大部分成熟的項目都會配置 JVM 參數。但是還是有一些小項目真的會忽略。以至於 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。

為了方便日志分析，我設置了一下簡單的 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]

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

在實際的生產環境中，只用簡單格式的 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。

垃圾收集的部分即是上圖中的「方法區」和「堆」兩部分。收集日志也基本上是描述這兩部分的大小和變化情況。

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

好了，基於上面的基礎認識。開始分析垃圾收集日志，以下是兩條日志，第一條是一次 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:畫個圖真是不容易），看一下各部分代表的含義。

上圖標注的是一條 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 區，通過下方的圖可以直觀的看出效果。

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]