G1ConcurrentMark is not triggered - why ?

[mwwojcik]

Hi ,
I would like to ask why, for this log, the G1ConcurrentMark event is not triggered? Is this the correct behaviour ?

[2023-07-18T18:57:21.853+0200][2189647.366s] GC(337607) Concurrent Mark Cycle
[2023-07-18T18:57:21.853+0200][2189647.366s] GC(337607) Concurrent Clear Claimed Marks
[2023-07-18T18:57:21.853+0200][2189647.366s] GC(337607) Concurrent Clear Claimed Marks 0.093ms
[2023-07-18T18:57:21.853+0200][2189647.366s] GC(337607) Concurrent Scan Root Regions
[2023-07-18T18:57:21.858+0200][2189647.371s] GC(337607) Concurrent Scan Root Regions 5.031ms
[2023-07-18T18:57:21.858+0200][2189647.371s] GC(337607) Concurrent Mark
[2023-07-18T18:57:21.858+0200][2189647.371s] GC(337607) Concurrent Mark From Roots
[2023-07-18T18:57:21.858+0200][2189647.371s] GC(337607) Using 1 workers of 1 for marking
[2023-07-18T18:57:21.995+0200][2189647.508s] GC(337607) Concurrent Mark From Roots 137.248ms
[2023-07-18T18:57:21.995+0200][2189647.508s] GC(337607) Concurrent Preclean
[2023-07-18T18:57:21.996+0200][2189647.509s] GC(337607) Concurrent Preclean 0.464ms
[2023-07-18T18:57:21.996+0200][2189647.509s] GC(337607) Pause Remark
[2023-07-18T18:57:22.031+0200][2189647.544s] GC(337607) Pause Remark 221M->211M(900M) 35.488ms
[2023-07-18T18:57:22.031+0200][2189647.545s] GC(337607) User=0.06s Sys=0.01s Real=0.04s
[2023-07-18T18:57:22.031+0200][2189647.545s] GC(337607) Concurrent Mark 173.515ms
[2023-07-18T18:57:22.031+0200][2189647.545s] GC(337607) Concurrent Rebuild Remembered Sets
[2023-07-18T18:57:22.093+0200][2189647.606s] GC(337607) Concurrent Rebuild Remembered Sets 61.364ms
[2023-07-18T18:57:22.093+0200][2189647.606s] GC(337607) Pause Cleanup
[2023-07-18T18:57:22.093+0200][2189647.606s] GC(337607) Pause Cleanup 217M->217M(900M) 0.245ms
[2023-07-18T18:57:22.093+0200][2189647.606s] GC(337607) User=0.00s Sys=0.00s Real=0.00s
[2023-07-18T18:57:22.093+0200][2189647.606s] GC(337607) Concurrent Cleanup for Next Mark
[2023-07-18T18:57:22.097+0200][2189647.611s] GC(337607) Concurrent Cleanup for Next Mark 4.063ms
[2023-07-18T18:57:22.097+0200][2189647.611s] GC(337607) Concurrent Mark Cycle 244.634ms

Best regards
Mario

[kcpeppe]

HI Mario, This appears to be a bug. Can you please attach the GC log and I'll apply a fix.

[mwwojcik]

Thank you,

I have prepared short log with Concurrent Mark : https://github.com/mwwojcik/mw-gc-wizard/blob/main/gclogs/g1-concurrent-mark.log

[kcpeppe]

awesome, I'll use it to debug.

[kcpeppe]

Hi Mario, there is no specific event for a "Concurrent Mark Cycle". The method below in the class UnifiedG1GCParser should start the recording of the concurrent phase.

    private void concurrentCycleStart(GCLogTrace trace, String line) {
        forwardReference.setConcurrentCycleStartTime(getClock());
        forwardReference.setGcType(GarbageCollectionTypes.Concurrent_Cycle);
    }

From here the parser should produce individual events for the concurrent mark, concurrent preClean, remark, cleanup and concurrent cleanup phases. These events will be emitted in time order.