gctoolkit icon indicating copy to clipboard operation
gctoolkit copied to clipboard

Unified log parser cannot collect safepoint information

Open dsgrieve opened this issue 2 years ago • 1 comments

Discussed in https://github.com/microsoft/gctoolkit/discussions/219

Originally posted by lalaorya July 4, 2022 I try to collect stw information from safepoint logs, here are my logs and aggregator

my vm args:-Xlog:safepoint=info:file=./logs/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M
[0.021s][info][gc] Using Parallel
[0.021s][info][gc,heap,coops] Heap address: 0x0000000700000000, size: 4096 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[0.601s][debug][safepoint    ] Safepoint synchronization initiated. (9 threads)
[0.601s][trace][safepoint    ] Setting thread local yield flag for threads
[0.601s][trace][safepoint    ] Thread: 0x00007fe11b009000  [0x1703] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11781b800  [0x4e03] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe117820800  [0x3303] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe117829800  [0x4403] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11782c800  [0x4303] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11782d800  [0x3a03] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11782e800  [0x3b03] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11a840000  [0x3d03] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][trace][safepoint    ] Thread: 0x00007fe11801e000  [0x5603] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
[0.601s][info ][safepoint    ] Entering safepoint region: Deoptimize
[0.601s][info ][safepoint    ] Leaving safepoint region
[0.601s][info ][safepoint    ] Total time for which application threads were stopped: 0.0003500 seconds, Stopping threads took: 0.0001490 seconds
@Aggregates({EventSource.SAFEPOINT})
public class SafePointAggregator extends Aggregator<SafePointAggregation> {
    public SafePointAggregator(SafePointAggregation aggregation) {
        super(aggregation);
        register(ApplicationStoppedTime.class,this::process);
        register(Safepoint.class,this::process);
    }

    private void process(ApplicationStoppedTime collection) {
        aggregation().recordApplicationStopTime(collection);
    }

    private void process(Safepoint collection) {
        aggregation().recordSafePoint(collection);
    }

By debug I found that GCToolkitVertxParametersForUnifiedLogs#initAggregatorVerticles has no safepoint related logic, which means that my aggregator is not loaded at all, and this was confirmed by debug. I don't think it's a bug, maybe there's something wrong with my code and I hope I can get an answer.

 private Set<AggregatorVerticle> initAggregatorVerticles(

        if (diary.isG1GC()) {}

        if (diary.isGenerational()) {}

        if (diary.isShenandoah()) {}

        if (diary.isZGC()) {}

        if (diary.isTenuringDistribution()) {}

    }

dsgrieve avatar Jul 05 '22 15:07 dsgrieve

Work in progress on branch issue_220

dsgrieve avatar Jul 13 '22 12:07 dsgrieve