Java GC Log Time解析

在分析應用服務性能時，我們常常會查看垃圾收集日志文件（gc.log）來追蹤gc活動的軌跡。在這些日志中，我們經常會看到每個gc事件的三種時間類型：”user”、”sys”和”real”。它們分別代表什么？具有哪些象征性意義？本文將結合實際經驗簡要解析這些時間類型，希望對大家在gc log分析和問題定位有所幫助。

以下是基于G1垃圾回收策略的GC Log內容，因篇幅有限，僅顯示部分內容：

[administrator@JavaLangOutOfMemory luga %]less echo-admin-gc.log ... ...2015-09-14T12:32:24.398-0700: 0.356: [GC pause (G1 Evacuation Pause) (young), 0.0215287 secs]   [Parallel Time: 20.0 ms, GC Workers: 8]      [GC Worker Start (ms): Min: 355.9, Avg: 356.3, Max: 358.4, Diff: 2.4]      [Ext Root Scanning (ms): Min: 0.0, Avg: 6.4, Max: 16.7, Diff: 16.7, Sum: 51.4]      [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.5, Diff: 2.5, Sum: 8.2]         [Processed Buffers: Min: 0, Avg: 1.1, Max: 5, Diff: 5, Sum: 9]      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]      [Object Copy (ms): Min: 2.9, Avg: 11.9, Max: 17.5, Diff: 14.6, Sum: 95.3]      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]         [Termination Attempts: Min: 1, Avg: 2.5, Max: 5, Diff: 4, Sum: 20]      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]      [GC Worker Total (ms): Min: 17.5, Avg: 19.6, Max: 19.9, Diff: 2.4, Sum: 156.5]      [GC Worker End (ms): Min: 375.8, Avg: 375.9, Max: 375.9, Diff: 0.1]   [Code Root Fixup: 0.0 ms]   [Code Root Purge: 0.0 ms]   [Clear CT: 0.5 ms]   [Other: 1.0 ms]      [Choose CSet: 0.0 ms]      [Ref Proc: 0.4 ms]      [Ref Enq: 0.0 ms]      [redirty Cards: 0.4 ms]      [Humongous Register: 0.0 ms]      [Humongous Reclaim: 0.0 ms]      [Free CSet: 0.0 ms]   [Eden: 12.0M(12.0M)->0.0B(14.0M) Survivors: 0.0B->2048.0K Heap: 12.6M(252.0M)->7848.3K(252.0M)] [Times: user=0.08 sys=0.00, real=0.02 secs] 2015-09-14T12:32:24.932-0700: 0.889: [GC pause (G1 Evacuation Pause) (young), 0.0469650 secs]

從上述輸出文件中，我們可以看到在年輕代GC事件后面有三種不同時間的詳細打印：

[Times: user=0.08 sys=0.00, real=0.02 secs]。關于如何在應用程序運行過程中輸出GC Log，可參考之前的文章：Java虛擬機三件套解析。

當我們拿到這份GC日志文件，常常會遇到許多問題：每個GC事件花費的時間都會在GC日志中報告。在每個GC事件中，都有“用戶”、“系統”和“實時”時間。它們代表什么意思？它們之間有什么本質區別？我們如何打印這些時間，以及在什么時間監控？

立即學習“Java免費學習筆記（深入）”；

在我們了解GC時間之前，先花幾分鐘了解linux/unix命令的“時間”。具體操作如下：

[administrator@JavaLangOutOfMemory ~ %] time lsDesktop      Movies      activemq    gateway      lugaDocuments    Music      cpu      go      monitoring-micrometerDownloads    Pictures    curl-format.txt    goPro      nacos-dockerIdeaProjects    Public      deploy-demo.yaml  java      openshiftLibrary      SpringCloud2.x    docker      k8sreal     0m0.003suser     0m0.000ssys      0m0.001s

通過time ls命令，我們看到這樣的輸出：

time ls命令首先顯示ls命令的執行輸出，其中列出了當前目錄中的所有目錄/文件：

接下來，我們看到執行ls所花費的時間，即：“真實”、“用戶”、“系統”時間。這是我們在GC日志中看到的相同數據。

下面是在每種情況下Stackoverflow中提供的一個很好的定義：

• Real（實際時間） 是掛鐘時間——從事件開始到結束的時間。這是所有經過的時間，包括其他進程使用的時間片以及該進程花費的時間被阻塞（例如，如果它正在等待I/O完成）。

• User（用戶時間） 是進程中用戶模式代碼（內核外部）所花費的CPU時間片。這只是執行過程中使用的實際CPU時間。該進程花費的其他進程和時間不計入該數字。

• Sys（系統時間） 是進程中在內核中花費的CPU時間量。這意味著在內核內部執行系統調用所花費的CPU時間，而不是庫代碼仍在用戶空間中運行。就像“用戶”一樣，這只是進程使用的CPU時間。

User + Sys將告訴我們：我們的進程使用了多少實際CPU時間。請注意，這涉及所有CPU，因此，如果該進程具有多個線程，則有可能超過Real Times的掛鐘時間。

剛才我們講到了Linux/Unix時間概念，現在我們著重看下Java GC Times。這與GC日志記錄中應用的概念相同。

在Java GC Times概念中，每個GC事件花費的時間都會在GC日志中報告。在每個GC事件中，都有“user”、“sys”和“real”。這些時間是什么意思？它們之間有什么區別？

• Real（實際時間） 指GC事件的總經過時間。這基本上是您在時鐘中看到的時間。

• User（用戶時間） 指用戶模式代碼（內核外部）所花費的CPU時間。

• Sys（系統時間） 指內核中花費的CPU時間。這意味著在內核內部執行系統調用所花費的CPU時間，而不是庫代碼仍在用戶空間中運行。

讓我們看幾個簡單示例，以便更好地理解這個概念。

示例1：

[Times: user=12.93 sys=2.01, real=1.03 secs]

在這個示例中：“user” + “sys”遠大于“real”。這是因為此日志時間是從jvm收集的，在JVM中，多核/多處理器服務器上配置了多個GC線程。當多個線程并行執行GC時，工作負載將在這些線程之間共享。因此，實際時鐘時間（“real”）比CPU總時間（“user” + “sys”）少得多。

示例2：

[Times: user=0.12 sys=0.00, real=0.12 secs]

上面是從串行垃圾收集器收集的GC時間的示例。由于串行垃圾收集器始終僅使用單個線程，因此實時等于用戶和系統時間的總和。

在實際的業務場景中，考慮性能優化時，我們主要偏向在為客戶優化響應時間。客戶不在乎我們使用多少GC線程或擁有多少處理器。因此，我們需要重點關注“real”時間，但這并不意味著“sys”或“user”時間并不重要。它們對于查看是否要增加GC線程數或CPU處理器數以減少GC暫停時間也很重要。

在正常的（所有）GC事件中，Real Time將小于（User+Sys）Time。這是因為多個GC線程同時工作以分擔工作量，因此實時時間將少于用戶+系統時間。假設（User+Sys）Time為2秒。如果5個GC線程同時工作，則實時應該在400毫秒左右（2秒/5個GC線程）附近。但是在某些情況下，我們可能會看到Real Time >（User+Sys）Time。

我們看一下示例：

[Times: user=0.80 sys=0.05, real=20.37 secs]

如果我們在GC日志中發現多次出現此情況（Real Time明顯大于User Time與Sys Time之和），則可能表明存在以下問題之一：

1. I/O繁忙
2. CPU不足

下面我們針對出現的性能問題進行分析：

I/O繁忙

當服務器上發生大量I/O活動（即網絡/磁盤訪問/用戶交互）時，實時性往往會在很大程度上飆升。作為GC日志記錄的一部分，我們的應用程序進行磁盤訪問。如果服務器上的I/O活動繁重，則GC事件可能會擱淺，從而導致實時峰值。

注意：即使我們的應用程序沒有引起繁重的I/O活動，服務器上的其他進程也可能導致繁重的I/O活動，從而導致較高的實時性。

我們可以在Linux/Unix中使用sar（系統活動報告）監視服務器上的I/O活動。具體為：

[administrator@JavaLangOutOfMemory ~ %]sar -d -p 1

上面的命令每1秒報告一次對設備的讀取/秒和寫入/秒。有關“sar”命令的更多詳細信息，請參官網教程。

如果我們發現服務器上的I/O活動很高，則可以執行以下任一操作來解決此問題：

1. 如果我們的應用程序引起了較高的I/O活動，請優化應用程序的I/O活動。
2. 消除導致服務器上大量I/O活動的進程。
3. 將我們的應用程序移到I/O活動較少的其他服務器上。

CPU不足

如果我們的服務器上正在運行多個進程，并且我們的應用程序沒有足夠的CPU周期來運行，它將開始等待。當應用程序開始等待時，實時將大大高于用戶+系統時間。

我們可以使用“top”之類的命令或監視工具（nagios，newRelic，AppDynamics…）來觀察服務器上的CPU利用率。如果我們發現CPU使用率很高，并且進程沒有足夠的周期來運行，則可以執行以下一項操作來解決此問題：

1. 減少服務器上正在運行的進程數，以便我們的應用程序有運行的資源空間。
2. 增加CPU容量，將應用服務移至具有更多CPU核心的更大實例類型。
3. 將我們的應用程序移到具有足夠CPU容量的新服務器上。

基于以上的解析過程，希望本文對大家有所幫助，使得我們能夠熟悉GC Log里面的奧秘，以便我們的應用程序在運行過程中以獲得最佳性能表現。