java - OracleJDK/Hotspot 9 GC 日志记录标志 - 如何查看 G1GC 中花费的时间

Question

在 OracleJDK/Hotspot 8 及以下版本中，我使用了这组标志:

-XX:+PrintAdaptiveSizePolicy
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCCause
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+UnlockCommercialFeatures
-XX:+UnlockExperimentalVMOptions
-XX:+UseG1GC

记录 G1GC 的事件。在旧的格式中，我能够在每个年轻的系列中看到，究竟花了多少时间。示例:

     2.130: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 26 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 3284.94 ms, target pause time: 40.00 ms]
, 0.0409345 secs]
   [Parallel Time: 36.4 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 2130.0, Avg: 2130.1, Max: 2130.2, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 0.9, Max: 1.9, Diff: 1.2, Sum: 7.5]
      [Update RS (ms): Min: 0.0, Avg: 0.9, Max: 1.5, Diff: 1.5, Sum: 7.1]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 2, Diff: 2, Sum: 9]
      [Scan RS (ms): Min: 5.9, Avg: 9.5, Max: 13.7, Diff: 7.8, Sum: 76.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 1.4, Diff: 1.4, Sum: 5.5]
      [Object Copy (ms): Min: 20.3, Avg: 24.0, Max: 27.0, Diff: 6.6, Sum: 191.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 193.6, Max: 248, Diff: 247, Sum: 1549]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 36.0, Avg: 36.1, Max: 36.2, Diff: 0.2, Sum: 289.0]
      [GC Worker End (ms): Min: 2166.3, Avg: 2166.3, Max: 2166.3, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 3.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 208.0M(11.0G)->0.0B(10.9G) Survivors: 0.0B->32.0M Heap: 212.0M(21.9G)->32.1M(21.9G)]
 [Times: user=0.22 sys=0.01, real=0.04 secs]

但是在我切换到 Oracle Hotspot JDK 9 之后。我根据 Oracle 文档将其更改为那些参数:

-Xlog:safepoint,gc*,gc+ergo*=trace,gc+age=trace

我看到的是:

[2018-05-03T11:39:16.592-0700][65.378s] GC(8) - age   1:  104795024 bytes,  104795024 total
[2018-05-03T11:39:16.592-0700][65.378s] GC(8) Running G1 Free Collection Set using 8 workers for collection set length 1404
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) MMU target violated: 41.0ms (40.0ms/41.0ms)
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Updating Refinement Zones: update_rs time: 0.495ms, update_rs buffers: 113, update_rs goal time: 3.590ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Updated Refinement Zones: green: 10, yellow: 30, red: 50
[2018-05-03T11:39:16.593-0700][65.379s] GC(8)   Pre Evacuate Collection Set: 0.2ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8)   Evacuate Collection Set: 314.6ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8)   Post Evacuate Collection Set: 6.1ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8)   Other: 0.5ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Eden regions: 1325->0(1389)
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Survivor regions: 79->15(176)
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Old regions: 9->81
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Humongous regions: 9->9
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Metaspace: 80171K->80171K(1124352K)
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) Pause Young (G1 Evacuation Pause) 11364M->830M(22472M) 321.378ms
[2018-05-03T11:39:16.593-0700][65.379s] GC(8) User=2.43s Sys=0.07s Real=0.32s

我的来源: https://blog.gceasy.io/2017/10/17/43-gc-logging-flags-removed-in-java-9/和 https://docs.oracle.com/javase/9/tools/java.htm#GUID-BE93ABDC-999C-4CB5-A88B-1994AAAC74D5__CONVERTRUNTIMELOGGINGFLAGSTOXLOG-A504703E

但是，我如何查看每个阶段实际花费的时间(对象复制与更新 RS..)

谢谢

Answer 1

最后的答案是添加

gc+phases*=debug

旗帜。

现在我可以了

2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Ext Root Scanning (ms):   Min:  0.5, Avg:  1.8, Max:  4.9, Diff:  4.4, Sum: 14.6, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Update RS (ms):           Min:  0.0, Avg:  1.2, Max:  2.4, Diff:  2.4, Sum:  9.2, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)       Processed Buffers:        Min: 0, Avg:  1.1, Max: 2, Diff: 2, Sum: 9, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Scan RS (ms):             Min:  2.5, Avg:  5.2, Max: 10.7, Diff:  8.2, Sum: 41.8, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Code Root Scanning (ms):  Min:  0.0, Avg:  0.4, Max:  1.3, Diff:  1.3, Sum:  3.0, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     AOT Root Scanning (ms):   skipped
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Object Copy (ms):         Min: 20.7, Avg: 26.2, Max: 28.2, Diff:  7.5, Sum: 209.9, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Termination (ms):         Min:  0.0, Avg:  0.1, Max:  0.2, Diff:  0.2, Sum:  1.1, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)       Termination Attempts:     Min: 1, Avg: 229.0, Max: 356, Diff: 355, Sum: 1832, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     GC Worker Other (ms):     Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.1, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     GC Worker Total (ms):     Min: 34.4, Avg: 35.0, Max: 35.3, Diff:  0.9, Sum: 279.7, Workers: 8
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)   Post Evacuate Collection Set: 1.8ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Code Roots Fixup: 0.1ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Preserve CM Refs: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Reference Processing: 1.2ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Clear Card Table: 0.1ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Reference Enqueuing: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Merge Per-Thread State: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Code Roots Purge: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Redirty Cards: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Clear Claimed Marks: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Free Collection Set: 0.4ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Humongous Reclaim: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)     Expand Heap After Collection: 0.0ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0)   Other: 0.3ms
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Eden regions: 15->0(1400)
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Survivor regions: 0->4(176)
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Old regions: 0->0
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Humongous regions: 1->1
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Metaspace: 20169K->20169K(1069056K)
[2018-05-08T16:18:26.671-0700][2.429s] GC(0) Pause Initial Mark (Metadata GC Threshold) 128M->32M(22472M) 37.796ms

这正是我要找的。

所以flags的最终命令组合是

  -Xlog:safepoint,gc*,gc+ergo*=trace,gc+age*=trace,gc+phases*=debug:file=/app/log/gc-%t.log:time,uptime:filecount=2,filesize=100M