NPE in c.m.g.sample.aggregation.HeapOccupancyAfterCollection.extractHeapOccupancy

[dsgrieve]

trafficstars

Don't dismiss as 'it's only a sample' as this may expose some underlying problem, or expose some lack of coverage in unit testing.

Describe the bug 022-10-31T20:35:27.3983818Z [INFO] Running com.microsoft.gctoolkit.integration.core.PreunifiedJavaVirtualMachineConfigurationTest 2022-10-31T20:35:27.9909813Z Oct 31, 2022 8:35:27 PM com.microsoft.gctoolkit.vertx.aggregator.AggregatorVerticle lambda$record$0 2022-10-31T20:35:27.9910852Z WARNING: Error in aggregator 2022-10-31T20:35:27.9912261Z java.lang.NullPointerException 2022-10-31T20:35:27.9913483Z at [email protected]/com.microsoft.gctoolkit.sample.aggregation.HeapOccupancyAfterCollection.extractHeapOccupancy(HeapOccupancyAfterCollection.java:27) 2022-10-31T20:35:27.9914614Z at [email protected]/com.microsoft.gctoolkit.aggregator.JVMEventDispatcher.dispatch(JVMEventDispatcher.java:77) 2022-10-31T20:35:27.9915751Z at [email protected]/com.microsoft.gctoolkit.aggregator.Aggregator.consume(Aggregator.java:118) 2022-10-31T20:35:27.9916766Z at [email protected]/com.microsoft.gctoolkit.vertx.aggregator.AggregatorVerticle$AggregatorWrapper.consume(AggregatorVerticle.java:38) 2022-10-31T20:35:27.9975222Z at [email protected]/com.microsoft.gctoolkit.vertx.aggregator.AggregatorVerticle.lambda$record$0(AggregatorVerticle.java:105) 2022-10-31T20:35:27.9975883Z at java.base/java.lang.Iterable.forEach(Iterable.java:75) 2022-10-31T20:35:27.9976860Z at [email protected]/com.microsoft.gctoolkit.vertx.aggregator.AggregatorVerticle.record(AggregatorVerticle.java:103) 2022-10-31T20:35:27.9977761Z at [email protected]/com.microsoft.gctoolkit.vertx.aggregator.AggregatorVerticle.lambda$start$2(AggregatorVerticle.java:137) 2022-10-31T20:35:27.9978422Z at [email protected]/io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264) 2022-10-31T20:35:27.9979046Z at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.dispatch(MessageConsumerImpl.java:177) 2022-10-31T20:35:27.9979717Z at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration$InboundDeliveryContext.execute(HandlerRegistration.java:137) 2022-10-31T20:35:27.9980354Z at [email protected]/io.vertx.core.eventbus.impl.DeliveryContextBase.next(DeliveryContextBase.java:72) 2022-10-31T20:35:27.9980912Z at [email protected]/io.vertx.core.eventbus.impl.DeliveryContextBase.dispatch(DeliveryContextBase.java:43) 2022-10-31T20:35:27.9981541Z at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration.dispatch(HandlerRegistration.java:98) 2022-10-31T20:35:27.9982183Z at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.deliver(MessageConsumerImpl.java:183) 2022-10-31T20:35:27.9982798Z at [email protected]/io.vertx.core.eventbus.impl.MessageConsumerImpl.doReceive(MessageConsumerImpl.java:168) 2022-10-31T20:35:27.9983426Z at [email protected]/io.vertx.core.eventbus.impl.HandlerRegistration.lambda$receive$0(HandlerRegistration.java:49) 2022-10-31T20:35:27.9984033Z at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) 2022-10-31T20:35:27.9984658Z at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) 2022-10-31T20:35:27.9985244Z at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) 2022-10-31T20:35:27.9985794Z at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) 2022-10-31T20:35:27.9986383Z at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) 2022-10-31T20:35:27.9986985Z at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) 2022-10-31T20:35:27.9987520Z at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) 2022-10-31T20:35:27.9987997Z at java.base/java.lang.Thread.run(Thread.java:829) To Reproduce Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
3. Scroll down to '....'
4. See error

Expected behavior A clear and concise description of what you expected to happen.

Screenshots If applicable, add screenshots to help explain your problem.

Desktop (please complete the following information):

• OS: [e.g. iOS]
• Browser [e.g. chrome, safari]
• Version [e.g. 22]

Smartphone (please complete the following information):

• Device: [e.g. iPhone6]
• OS: [e.g. iOS8.1]
• Browser [e.g. stock browser, safari]
• Version [e.g. 22]

Additional context Add any other context about the problem here.

[gofow]

Hi, I'd like to do this. Maybe this NPE problem is caused by something due to multithreading. Although it is hard to reproduce and has a very low probability of occurrence, my suggestion is to add 'is null' check before invoking a method. It will be more robust and prescriptive. Would you mind assigning the issue to me? @dsgrieve @karianna

[kcpeppe]

@gofow, happy to have you tackle this issue. We had a problem that feels similar when testing with machines that had low core counts. The issue was that vert.x wasn't fully started before the log file streaming started. The test failed because the initial part of the log was dropped by vert.x. This was fixed by adjusting the code that ensured vert.x verticles were fully started prior to streaming the log. Not saying this is the issue but it feels like a chunk of the log file is getting dropped instead of being pushed forward to the Aggregations or the Aggregations are being read before the stream has been fully processed. Or, it could be something completely else. I can't reproduce it so it's all speculation

[gofow]

@kcpeppe Yes, you're right. BTW, I was wondering how you ensure that the vert.x verticles are fully started prior to streaming the log? And thank you for sharing your insights. It will be very inspiring and helpful for me.

[kcpeppe]

We use a phaser up front to create a starting line and then there is shutdown code in the verticle which can be used to sync the shutdown. You can find it all in the vert.x module