Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Lambda stack trace missing when using NativeMethodAccessor instead of GeneratedMethodAccessor

A couple days ago, I got a support ticket for this NullPointerException:

com.google.gwt.user.server.rpc.UnexpectedException: Service method 'public abstract com.redacted.SalesResponsePagination com.redacted.StatisticsService.findSalesData(com.redacted.ConfStats) throws com.redacted.AsyncException' threw an unexpected exception: java.lang.NullPointerException
    at com.google.gwt.user.server.rpc.RPC.encodeResponseForFailure(RPC.java:389)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:579)
    at ... (typical GWT + Tomcat stacktrace)
Caused by: java.lang.NullPointerException
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
    at java.lang.reflect.Constructor.newInstance(Unknown Source)
    at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at com.redacted.StatisticsControllerImpl.replacePrices(StatisticsControllerImpl.java:310)
    at com.redacted.StatisticsControllerImpl.findSalesData(StatisticsControllerImpl.java:288)
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.GeneratedMethodAccessor752.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
    ... 33 more
Caused by: java.lang.NullPointerException
    at com.redacted.StatisticsControllerImpl.lambda$replacePrices$27(StatisticsControllerImpl.java:317)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(Unknown Source)
    at ... (typical stream.forEach stacktrace)

Now, this was an easy one because the exact line number for the NPE was in plain sight; all I had to do was go to StatisticsControllerImpl.java:317:

    salesResponsePagination.getSalesResponses().parallelStream()
            .peek(sr -> /*...*/)
            .filter(sr -> /*...*/)
/*310*/     .forEach(sr -> {
                final List<CartElement> sentCEs = DaoService.getCartElementDAO().getSentCEs(/*...*/);
                if (sentCEs != null && !sentCEs.isEmpty() && sentCEs.get(0) != null) {
                    final CartElement ce = sentCEs.get(0);
                    // some more non-NPE lines...
/*317*/             if (sr.getCurrency().equals(ce.getPurchaseCurrency()) && sr.getPrice().equals(ce.getPurchasePrice().intValue()) && !ce.getCurrency().equals(ce.getPurchaseCurrency())) {
                        // Some currency exchanging
                    }
                    // Etcetera (about 12 lines more)
            });

And replace the .equals() calls with Object.equals() to avoid the NPE (investigating the reasons why some sales were registered with a NULL price or currency came later). Test, commit, push, send ticket to QA.

However, the next day QA returned the ticket saying that the NPE persisted, and they included a new, almost similar stack trace:

com.google.gwt.user.server.rpc.UnexpectedException: Service method 'public abstract com.redacted.SalesResponsePagination com.redacted.StatisticsService.findSalesData(com.redacted.ConfStats) throws com.redacted.AsyncException' threw an unexpected exception: java.lang.NullPointerException
    at com.google.gwt.user.server.rpc.RPC.encodeResponseForFailure(RPC.java:389)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:579)
    at ... (typical GWT + Tomcat stacktrace)
Caused by: java.lang.NullPointerException
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
    at java.lang.reflect.Constructor.newInstance(Unknown Source)
    at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
    at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(Unknown Source)
    at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
    at java.util.stream.ReferencePipeline.forEach(Unknown Source)
    at com.redacted.StatisticsControllerImpl.replacePrices(StatisticsControllerImpl.java:310)
    at com.redacted.StatisticsControllerImpl.findSalesData(StatisticsControllerImpl.java:288)
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:561)
    ... 33 more
Caused by: java.lang.NullPointerException

This stack trace was exactly the same as the previous one, except for two things:

  • This call was using NativeMethodAccessorImpl instead of GeneratedMethodAccessor752. Compare:
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.GeneratedMethodAccessor752.invoke(Unknown Source)
    vs
    at com.redacted.StatisticsServiceImpl.findSalesData(StatisticsServiceImpl.java:83)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

  • This one was missing the stack trace for the lambda. The line where the NPE happened was missing.

This threw me off initially. Why was the last part of the stack trace missing? I asked QA to re-test and re-attach the stack trace a couple times, until I got a complete one; however, the complete one I got in the end was based on GeneratedMethodAccesor once again.

Now, if I understand correctly, sun.reflect.NativeMethodAccessorImpl is used for the first invocations of a method, until JIT has enough info to generate an optimized accesor for that method in the form of sun.reflect.GeneratedMethodAccessorNNN.
What I don't understand is: if Native is using my code and Generated is using JIT's generated code, shouldn't Native show more info about my code, not less?

So my question is:
Why do lambda runtime exceptions thrown inside sun.reflect.NativeMethodAccessorImpl seem to be missing the lambda's stack trace?

Can this be a bug in JDK's source code? Especially when the very same exception thrown inside sun.reflect.GeneratedMethodAccessor includes the lambda stack trace without problem.


The following code manages to get a stack trace similar to the first one. I can force the use of NativeMethodAccessor or GeneratedMethodAccesor by running it with a sufficiently low or high first parameter, respectively (i.e. java test.Main 1 or java test.Main 30).
However, the lambda part of it is always present, whether using Native or Generated.

package test;

import java.lang.reflect.Method;
import java.util.stream.IntStream;

class MyOtherClass {
    public void methodWithLambda(boolean fail) {
        IntStream.range(0, 1000).parallel().forEach(k -> {
            if (fail && k % 500 == 0)
                throw new NullPointerException();
        });
    }
    public String methodProxy(boolean fail) {
        methodWithLambda(fail);
        return "OK";
    }
}

class MyClass {
    public String methodReflected(Boolean fail) {
        return new MyOtherClass().methodProxy(fail);
    }
}

class Main {
    public static void main(String[] args) throws Exception {
        Class<MyClass> clazz = MyClass.class;
        Object instance = clazz.newInstance();
        Method method = clazz.getMethod("methodReflected", Boolean.class);
        int reps = args.length >= 1 ? Integer.valueOf(args[0]) : 20; 
        for (; reps --> 0;) {
            // Several non-failing calls to force creation of GeneratedMethodAccesor
            System.out.println((String) method.invoke(instance, false));
        }
        // Failing call
        System.out.println((String) method.invoke(instance, true));
    }
}

Stack trace for the above code when using NativeMethodAccesor:

Exception in thread "main" java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
        at java.lang.reflect.Method.invoke(Unknown Source)
        at test.Main.main(Main.java:36)
Caused by: java.lang.NullPointerException
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
        at java.lang.reflect.Constructor.newInstance(Unknown Source)
        at java.util.concurrent.ForkJoinTask.getThrowableException(Unknown Source)
        at java.util.concurrent.ForkJoinTask.reportException(Unknown Source)
        at java.util.concurrent.ForkJoinTask.invoke(Unknown Source)
        at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(Unknown Source)
        at java.util.stream.ForEachOps$ForEachOp$OfInt.evaluateParallel(Unknown Source)
        at java.util.stream.AbstractPipeline.evaluate(Unknown Source)
        at java.util.stream.IntPipeline.forEach(Unknown Source)
        at java.util.stream.IntPipeline$Head.forEach(Unknown Source)
        at test.MyOtherClass.methodWithLambda(Main.java:8)
        at test.MyOtherClass.methodProxy(Main.java:14)
        at test.MyClass.methodReflected(Main.java:21)
        ... 5 more
Caused by: java.lang.NullPointerException
        at test.MyOtherClass.lambda$methodWithLambda$0(Main.java:10)
        at java.util.stream.ForEachOps$ForEachOp$OfInt.accept(Unknown Source)
        at java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Unknown Source)
        at java.util.Spliterator$OfInt.forEachRemaining(Unknown Source)
        at java.util.stream.AbstractPipeline.copyInto(Unknown Source)
        at java.util.stream.ForEachOps$ForEachTask.compute(Unknown Source)
        at java.util.concurrent.CountedCompleter.exec(Unknown Source)
        at java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
        at java.util.concurrent.ForkJoinPool$WorkQueue.execLocalTasks(Unknown Source)
        at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(Unknown Source)
        at java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
        at java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)

EDIT: Just to be clear: I am not looking for ways to fix this NPE, nor ways to force the lambda's stack trace to print. What I want to know is the reason why the above happens: different implementations? A bug? Something to do with forEach()?

like image 272
walen Avatar asked Jan 15 '19 10:01

walen


1 Answers

This might be an issue of JDK-6678999, “Stacktrace missing after null string comparisons”:

After comparing a string to null and catching the exception and repeating the operation, JVM starts throwing "stackless" NullPointerException (it occurs after 9000 loops but this is variable)

The evaluation of the issue is

When the server compiler compiles a method, the stack trace in an exception thrown by that method may be omitted for performance purposes.

[…] If the user always wants stack traces, use the -XX:-OmitStackTraceInFastThrow option to the VM.

So, the option -XX:-OmitStackTraceInFastThrow may solve the issue.

Note that the bug report was against Java 6, but since it has been closed as “Won't Fix”, it may still be relevant, though you would have to replace “server compiler” with “c2 compiler” in the explanation now.

The use of NativeMethodAccessorImpl or GeneratedMethodAccessor… is not relevant to this issue, except that both have a common cause; a higher number of executions may trigger the optimizations.

like image 75
Holger Avatar answered Sep 22 '22 16:09

Holger