NPE in Aggregation.estimatedStartTime() when processing a Pre-Unified GC log with timestamps only.
Closed this issue · 6 comments
Describe the bug
When loading the attached file, the following NPE is encountered:
Mar 13, 2024 2:33:24 PM com.microsoft.gctoolkit.jvm.AbstractJavaVirtualMachine analyze INFO: No Aggregations have been registered, DataSource will not be analysed. Mar 13, 2024 2:33:24 PM com.microsoft.gctoolkit.jvm.AbstractJavaVirtualMachine analyze INFO: Is there a module containing Aggregation classes on the module-path Mar 13, 2024 2:33:24 PM com.microsoft.gctoolkit.jvm.AbstractJavaVirtualMachine analyze INFO: Is GCToolKit::loadAggregationsFromServiceLoader() or GCToolKit::loadAggregation(Aggregation) being invoked? Mar 13, 2024 2:33:24 PM com.microsoft.gctoolkit.GCToolKit analyze SEVERE: Internal Error: Cannot invoke analyze method java.lang.NullPointerException at com.microsoft.gctoolkit.aggregator.Aggregation.estimatedStartTime(Aggregation.java:140) at com.microsoft.gctoolkit.aggregator.Aggregation.estimatedRuntime(Aggregation.java:154) at com.microsoft.gctoolkit.jvm.AbstractJavaVirtualMachine.lambda$5(AbstractJavaVirtualMachine.java:193) at java.base/java.util.Optional.ifPresent(Optional.java:183) at com.microsoft.gctoolkit.jvm.AbstractJavaVirtualMachine.analyze(AbstractJavaVirtualMachine.java:191) at com.microsoft.gctoolkit.GCToolKit.analyze(GCToolKit.java:313) ... continues ...
Sample File Reproducing Issue: gc.out.3.zip
Debugger shows that timeOfFirstEvent is null at this point, triggering the NPE. timeOfTermination is not null, but is set to 0.0/Windows Epoch.
To Reproduce
Steps to reproduce the behavior:
Attempt to analyze the attached file. Problem reproduces with the sample application when scanning the attached file.
Expected behavior
timeOfFirstEvent would be set to 9.089 to match first line in file.
Desktop (please complete the following information):
- OS: Windows 10, Java 11.0.19_7
- GCToolkit: Reproducible in both head-rev (Mar 13, 2024) and 3.0.4.
@kcpeppe are you able to take a look before we cut the next release? Note this bug was on tip
I believe bug has been addressed in the current PR
Does that mean that the change is in place and I can validate it with the current tip, or is it still pending a merge?
I'm still able to reproduce the issue locally, though I'm not able to reproduce the problem with the sample app or with a very basic implementation using current tip (April 9, 2024).
I'm going to look into this some more, and will post an update when I figure out what the problem is, but I'm not 100% certain it's in the library code.
@Bluetopia - Do you have your own Aggregator/Aggregations? If so, is it one of those that is giving you the NPE? And if so, are you sure the aggregators are receiving events and that the aggregation are collecting data? If the code is trying to get the estimatedStartTime from an aggregation that is never called, then you'll get the NPE.
A lot of things can happen that will cause an Aggregator/Aggregation to be excluded. If you set -Dgctoolkit.debug=true you will get some additional debug info printed to System.out. If there is some issue with how your Aggregator/Aggregations are wired, you'll see that right away. By "wired" I mean all of the ceremony of @Aggregates, @Collates and a public Aggregator constructor that takes the proper type of Aggregation.
@kcpeppe - You should run the gc log that Bluetopia attached to this issue through the Main program in the sample directory. Are those the results you'd expect?
@dsgrieve Turns out it was a case of PEBCAK.
The project was pulling an old version of the library and using it rather than tip. I've fixed the build issue on my end and have confirmed the NPE is gone with the updates.
We can close this, or you can close it with 3.0.5 release, depending on which you prefer.