NullPointerException when processing file without GC Events

[Bluetopia]

Describe the bug
A NullPointerException is thrown when processing a file that contains no GC events.

The JVM does not return after this NPE occurs. (Have to kill the process manually)

Callstack:

java.lang.NullPointerException: Cannot invoke "com.microsoft.gctoolkit.time.DateTimeStamp.add(double)" because the return value of "com.microsoft.gctoolkit.parser.GCLogParser.getClock()" is null
        at [email protected]/com.microsoft.gctoolkit.parser.GCLogParser.receive(GCLogParser.java:97)
        at [email protected]/com.microsoft.gctoolkit.parser.GCLogParser.receive(GCLogParser.java:21)
        at [email protected]/com.microsoft.gctoolkit.vertx.DataSourceVerticle.lambda$start$0(DataSourceVerticle.java:36)
        at [email protected]/io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:279)
        at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.dispatch(MessageConsumerImpl.java:177)
        at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration$InboundDeliveryContext.execute(HandlerRegistration.java:137)
        at [email protected]/io.vertx.core.eventbus.impl.DeliveryContextBase.next(DeliveryContextBase.java:80)
        at [email protected]/io.vertx.core.eventbus.impl.DeliveryContextBase.dispatch(DeliveryContextBase.java:43)
        at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration.dispatch(HandlerRegistration.java:98)
        at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.deliver(MessageConsumerImpl.java:183)
        at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.doReceive(MessageConsumerImpl.java:168)
        at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration.lambda$receive$0(HandlerRegistration.java:49)
        at [email protected]/io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
        at [email protected]/io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
        at [email protected]/io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
        at [email protected]/io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
        at [email protected]/io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at [email protected]/io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at [email protected]/io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)

Sample File

Java HotSpot(TM) 64-Bit Server VM (25.202-b08) for linux-amd64 JRE (1.8.0_202-b08), built on Dec 15 2018 12:40:22 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 16264752k(377768k free), swap 0k(0k free)
CommandLine flags: -XX:+DisableExplicitGC -XX:GCLogFileSize=134217728 -XX:InitialHeapSize=150994944 -XX:+ManagementServer -XX:MaxHeapSize=150994944 -XX:NumberOfGCLogFiles=4 -XX:ParallelGCThreads=2 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:-TieredCompilation -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC 
Heap
 PSYoungGen      total 43008K, used 12467K [0x00000000fd000000, 0x0000000100000000, 0x0000000100000000)
  eden space 36864K, 33% used [0x00000000fd000000,0x00000000fdc2cda0,0x00000000ff400000)
  from space 6144K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x0000000100000000)
  to   space 6144K, 0% used [0x00000000ff400000,0x00000000ff400000,0x00000000ffa00000)
 ParOldGen       total 98304K, used 0K [0x00000000f7000000, 0x00000000fd000000, 0x00000000fd000000)
  object space 98304K, 0% used [0x00000000f7000000,0x00000000f7000000,0x00000000fd000000)
 Metaspace       used 7756K, capacity 7884K, committed 7936K, reserved 1056768K
  class space    used 935K, capacity 986K, committed 1024K, reserved 1048576K

To Reproduce
Steps to reproduce the behavior:
1: Using the sample application, attempt to analyze the file above.
mvnw.cmd exec:exec -DgcLogFile=sample.out
2: NPE above is thrown. Process hangs in place until terminated manually (Ctrl-C, or killing the JVM)

Expected behavior
File is successfully analyzed (even if no data is available) or a suitable error is returned.

Desktop (please complete the following information):

• OS: Windows 11
• GCToolkit Version: Tip commit f9c62c6 (Bump actions/checkout from 4.1.3 to 4.1.4 #350)
• Java: Reproduced on Java 17 and Java 11.

[Bluetopia]

Some further observations:

• It doesn't appear that the library performs any format validation on the files it processes. I was able to reproduce the NPE with a generic text file containing no GC data.
• There are a few places where assumptions are made around the sanity of the data. For example, if you were to put a null check before the assignment at GCLogParser:43 such that the Diary retains its default Epoch initialization, we run into errors later in the aggregation when calculating an estimated Start time (Aggregation:140). If no events were logged in the Diary, should we even make it to this point?

I understand that there is only so much that a library should do when it comes to handling unexpected input; the application using the library has to bear some of that responsibility. However, it seems problematic that invalid input can put the library into a state that hangs the JVM with a relatively simple use case.

[kcpeppe]

Agreed on all points.

[Lmh-java]

I would love to give a shot on this issue.

[karianna]

I would love to give a shot on this issue.

Please go ahead!

[kcpeppe]

@Lmh-java, I will freely admit that this case isn't well covered as the assumption has always been that the log file presented has GC events in it. It's just not something that I see happening enough to care about it all that much but this doesn't mean that something shouldn't be done to cover this off. That said, here is some information that you may find useful.

Setup if controlled by the diarization process. It looks for features in the file to build up a diary. This diary is used by GCToolKit when it is making certain decisions such as which parsers to instantiate. In pre-unified logs, it is used to report on flags used to created the log file. This was used to support an analytic that allowed us to guide the user to more useful JVM flag configurations.

The diary process is setup to only look into the log file until it finds all that it needs to know or has looked 10k lines. The assumption being that the diarization should have found everything it needs to know by then. There are only a couple of edge cases where this assumption fails (such as a simple log for CMS in which no CMS cycles are present) but this is only for pre-unified logging so, generally works good enough for purpose.

If there is enough information in the header then the diarizer will take the info from that and continue without looking deeper into the file. In this case parsers will be instantiated and the file will be streamed to them. If the file only contains headers and no GC events, then the only event emitted should be a JVMTermination event. However, this case isn't tested for or TBH, hasn't been thought through so anything that can be added here would be exceptionally useful.

The only potential conflict here is that I've added support for genZ. Since this is a new feature I'll be adjusting diarization to be able to recognize and report on it. This should be checked in soon.

[Lmh-java]

Thanks for your detailed explanation on the diary process. I am relatively new to this project, and I am currently working on understanding the entire logic and coming up with a plan to address this issue.