microsoft/gctoolkit

YoungDetails event not published for GC log collected with -Xlog:gc (no *)

Opened this issue · 0 comments

Describe the bug
The attached file seems to be generated by using the options -Xlog:gc (not -Xlog:gc*). Without the *, only the events tagged "gc" are written out.

[6.837s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 79M->27M(1024M) 2.929ms
[7.292s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 74M->28M(1024M) 3.038ms
[7.619s][info][gc] GC(5) Pause Young (Concurrent Start) (Metadata GC Threshold) 46M->30M(1024M) 4.745ms
[7.620s][info][gc] GC(6) Concurrent Cycle
[7.629s][info][gc] GC(6) Pause Remark 31M->31M(1024M) 2.697ms
[7.631s][info][gc] GC(6) Pause Cleanup 31M->31M(1024M) 0.073ms
[7.632s][info][gc] GC(6) Concurrent Cycle 11.893ms

While I originally mistakenly thought there was a mismatch on the rule, Events 3 and 4 do successfully match the YOUNG_DETAILS parse rule. However, I suspect the problem is that the forwardReference is populated by UnifiedG1GCParser.youngDetails(), there is nothing in the log file to cause the forwardReference to be published.

I confirmed this behaviour by setting up breakpoints on all publish*() methods in the class.

The output for -Xlog:gc* is more verbose and contains a line that triggers the publish:

[2024-08-07T13:31:02.129-0400][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2024-08-07T13:31:02.130-0400][gc,task      ] GC(0) Using 10 workers of 10 for evacuation
[2024-08-07T13:31:02.133-0400][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.0ms
[2024-08-07T13:31:02.133-0400][gc,phases    ] GC(0)   Evacuate Collection Set: 2.5ms
[2024-08-07T13:31:02.133-0400][gc,phases    ] GC(0)   Post Evacuate Collection Set: 0.2ms
[2024-08-07T13:31:02.133-0400][gc,phases    ] GC(0)   Other: 1.4ms
[2024-08-07T13:31:02.135-0400][gc,heap      ] GC(0) Eden regions: 12->0(10)
[2024-08-07T13:31:02.135-0400][gc,heap      ] GC(0) Survivor regions: 0->2(2)
[2024-08-07T13:31:02.135-0400][gc,heap      ] GC(0) Old regions: 0->3
[2024-08-07T13:31:02.135-0400][gc,heap      ] GC(0) Humongous regions: 0->0
[2024-08-07T13:31:02.135-0400][gc,metaspace ] GC(0) Metaspace: 8124K->8124K(1056768K)
[2024-08-07T13:31:02.135-0400][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 24M->8M(508M) 6.285ms
[2024-08-07T13:31:02.135-0400][gc,cpu       ] GC(0) User=0.02s Sys=0.00s Real=0.01s

To Reproduce
Steps to reproduce the behavior:

  • Should be possible to see that none of the publish methods in UnifiedG1GCParser are being hit with the sample application and the provided file.
  • gc.out.4.zip

Expected behavior
The parser should still be able to process files generated by -Xlog:gc. One way would be to publish if the event ID changes and the forwardReference object contains sufficient information for a trackable event.

Desktop (please complete the following information):

  • OS: Windows 11 (File was generated on Windows Server 2022)
  • Amazon Corretto 11.0.19.7