在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，三者的區別和含義如下：
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 過程存在某些問題（等待計算資源），原因可能是下面這兩種：
繁忙的i/o操作
當程式存在繁忙的i/o操作（網路io或磁碟io）時，會讓real時間大幅上公升。因為在記錄gc日誌的時候，你的程式進行了磁碟讀寫，如果同一時間其他io操作較重，則此時gc事件會延遲，進而影響了最終的real的值。注意，如果程式本身不存在的頻繁的io操作，同一機器上其他程序的頻繁io也會影響real的最終結果。linux環境下可以使用sar監視機器上的i/o，eg.sar -d -p 1，如果頻繁的io操作的確存在，可以通過下面兩種方式改進：
缺乏cpu資源
當程式本身是cpu密集型應用，或機器上其他程序占用了大量的cpu計算資源，則有可能會出現分配不到 cpu cycles的情況，這會讓程式掛起，gc所花費的實際時間也將遠大於user+sys的值。
可以使用top命令觀察一下 程序的cpu利用率，同時輔以profiler工具統計一段時間內程序的狀態分布。如果的確是cpu資源不足，解決方法無法下面幾種：
GC日誌分析
psyounggen gc型別 使用 xx useparalleloldgc 新生代，老年代都使用並行 收集器 或者 xx useparallelgc 新生代使用並行 收集器，老年代使用序列收集器 6577k younggc前新生代記憶體占用 1016k younggc後新生代記憶體占用 9216k...
GC之CMS GC日誌分析
最近在學習jvm和gc調優,今天總結下cms的一些特點和要點,首先貼上乙個實際的cms gc log,先來解讀下各個元素。從下面的gc日誌可以看出,當前最新版本 jdk1.8 中的cms大致分為6步 1.cms initial mark 初始標記 2.cms concurrent mark 併發標記...
GC日誌格式
2017 03 20t04 06 02.824 0800 3319.193 gc allocation failure psyounggen 6970156k 9232k 6 974464k 16059560k 9098683k 20955648k 0.0161336 secs times user...