microsoft / gctoolkit

Tool for parsing GC logs
https://github.com/microsoft/gctoolkit
MIT License
1.25k stars 153 forks source link

Unified log parser cannot collect safepoint information #220

Open dsgrieve opened 2 years ago

dsgrieve commented 2 years ago

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 { 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 initAggregatorVerticles( if (diary.isG1GC()) {} if (diary.isGenerational()) {} if (diary.isShenandoah()) {} if (diary.isZGC()) {} if (diary.isTenuringDistribution()) {} } ```
dsgrieve commented 2 years ago

Work in progress on branch issue_220