在GC日志里，一條完整的GC日志記錄最后，會帶有本次GC所花費的時間，如下面這一條新生代GC：
[GC [DefNew: 3298K->149K(5504K), 0.0053498 secs] 3298K->3221K(9600K), .0053750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
注意到日志中時間分為了三塊：user， sys，和 real，三者的區別和含義如下：
-
real：指的是在此次GC事件中所花費的總時間； -
user：指的是CPU工作在用戶態所花費的時間； -
sys：指的是CPU工作在內核態所花費的時間。
user + sys 就是CPU花費的實際時間，注意這個值統計了所有CPU上的時間，如果進程工作在多線程的環境下，這個值是會超出 real 所記錄的值的，即 user + sys >= real
對於GC事件來說，無論是 Minor GC 還是 Full GC 的過程，都存在並發的GC算法，如新生代的ParNew，老年代的ParallelOld，GC過程中工作負載是由多個線程共同完成的，這也就意味着使用這些GC算法時，GC日志中我們應該觀察到：user + sys > real。譬如說：配置了ParNew且並發數為5的GC活動（-XX:+UseParNewGC -XX:ParallelGCThreads=5）中，如果user + sys的值為 2 seconds，那么 real 的時間 就近似為 400ms(2 seconds / 5)。
場景1：
[Times: user=11.53 sys=1.38, real=1.03 secs]
垃圾回收過程是通過並發執行，因此 user + sys 遠大於 real 。
場景2：
[Times: user=0.09 sys=0.00, real=0.09 secs]
因為使用了串行的垃圾回收期，所以時間應該是 user 和 real 相等。
場景3：
[Times: user=0.20 sys=0.01, real=18.45 secs]
這是一個異常的示例，可以看到 real 所顯示的時間 遠 大於 user + sys。一般來說，如果觀察到GC日志里多次出現了場景3所示的日志，這表明JVM的GC 過程存在某些問題（等待計算資源），原因可能是下面這兩種：
- 頻繁的IO操作
- 缺乏CPU資源
繁忙的I/O操作
當程序存在繁忙的I/O操作（網絡IO或磁盤IO）時，會讓 real 時間大幅上升。因為在記錄GC日志的時候，你的程序進行了磁盤讀寫，如果同一時間其他IO操作較重，則此時GC事件會延遲，進而影響了最終的 real 的值。注意，如果程序本身不存在的頻繁的IO操作，同一機器上其他進程的頻繁IO也會影響 real 的最終結果。Linux環境下可以使用 sar 監視機器上的I/O，eg. sar -d -p 1，如果頻繁的IO操作的確存在，可以通過下面兩種方式改進：
- 優化程序本身的IO操作邏輯；
- 消除其他進程帶來的IO影響。
缺乏CPU資源
當程序本身是CPU密集型應用，或機器上其他進程占用了大量的CPU計算資源，則有可能會出現分配不到 CPU cycles的情況，這會讓程序掛起，GC所花費的實際時間也將遠大於 user + sys 的值。
可以使用 top 命令觀察一下 進程的CPU利用率，同時輔以Profiler工具統計一段時間內進程的狀態分布。如果的確是CPU資源不足，解決方法無法下面幾種：
- 優化程序內部的線程使用，確保無冗余的線程配置；
- 增加虛擬機或容器的CPU配置，提升機器總的計算能力。