Флаги журналирования 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

Однако, как я могу узнать, сколько времени на самом деле тратится на каждом из этапов (Object Copy vs Update 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

Что я и искал.

Итак, последняя комбинация флагов:

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