jaotc: Error: Failed compilation due to NullPointerException

[tianxiaogu]

jaotc crashed in Oracle JDK 9.0.4+11 and failed compilation in OpenJDK head.

Command:

jaotc --output C0.so --compile-commands commands.txt --verbose C0.class

Files:

https://drive.google.com/open?id=1p2qRGKtRkayhoWdZG6tYdNSEaZfDWx3F

Output with JDK 9.0.4+11

time ../../jdk-9.0.4/bin/jaotc --output C0.so --compile-commands commands.txt --verbose C0.class
Compiling C0...
1 classes found (25 ms)
 Scanning C0
  added main([Ljava/lang/String;)V
6 methods total, 1 methods to compile (4 ms)
Freeing memory [used: 2.1 MB , comm: 8.0 MB , freeRatio ~= 73.3%] (21 ms)
Compiling with 8 threads
.#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007fa81984615e, pid=11288, tid=11322
#
# JRE version: Java(TM) SE Runtime Environment (9.0+11) (build 9.0.4+11)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (9.0.4+11, mixed mode, aot, tiered, jvmci, compressed oops, g1 gc, linux-amd64)
# Problematic frame:
# J 2351 c2 org.graalvm.compiler.phases.schedule.SchedulePhase$Instance.sortIntoList(Lorg/graalvm/compiler/graph/Node;Lorg/graalvm/compiler/nodes/cfg/Block;Ljava/util/ArrayList;Lorg/graalvm/compiler/graph/NodeMap;Lorg/graalvm/compiler/graph/NodeBitMap;Lorg/graalvm/compiler/graph/Node;)V jdk.internal.vm.compiler@9.0.4 (153 bytes) @ 0x00007fa81984615e [0x00007fa819845760+0x00000000000009fe]
#
# Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport %p %s %c %d %P" (or dumping to /home/t/Projects/JVMTesting/bugs/jaotc-jdk-20180125165244/core.11288)
#
# An error report file with more information is saved as:
# /home/t/Projects/JVMTesting/bugs/jaotc-jdk-20180125165244/hs_err_pid11288.log
Could not load hsdis-amd64.so; library not loadable; PrintAssembly is disabled
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#
Aborted (core dumped)

real	1m56.242s
user	2m8.084s
sys	0m0.460s

Output with OpenJDK head

time ../../openjdk/jdk/build/linux-x86_64-normal-server-release/jdk/bin/jaotc --output C0.so --compile-commands commands.txt --verbose C0.class
Compiling C0.so...
1 classes found (229 ms)
 Scanning C0
  added main([Ljava/lang/String;)V
6 methods total, 1 methods to compile (6 ms)
Freeing memory [used: 4.3 MB , comm: 17.0 MB, freeRatio ~= 74.7%] (24 ms)
Compiling with 8 threads
.Error: Failed compilation: C0.main([Ljava/lang/String;)V: java.lang.NullPointerException
java.lang.NullPointerException
	at jdk.internal.vm.compiler/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.getInput(NodeClass.java:1042)
	at jdk.internal.vm.compiler/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.forward(NodeClass.java:981)
	at jdk.internal.vm.compiler/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.hasNext(NodeClass.java:974)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.schedule.SchedulePhase$Instance.scheduleEarliestIterative(SchedulePhase.java:743)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.schedule.SchedulePhase$Instance.run(SchedulePhase.java:167)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.schedule.SchedulePhase.run(SchedulePhase.java:126)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.Phase.run(Phase.java:47)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:195)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.Phase.apply(Phase.java:40)
	at jdk.internal.vm.compiler/org.graalvm.compiler.virtual.phases.ea.EffectsPhase.runAnalysis(EffectsPhase.java:87)
	at jdk.internal.vm.compiler/org.graalvm.compiler.virtual.phases.ea.PartialEscapePhase.run(PartialEscapePhase.java:80)
	at jdk.internal.vm.compiler/org.graalvm.compiler.virtual.phases.ea.PartialEscapePhase.run(PartialEscapePhase.java:42)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:195)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:137)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.PhaseSuite.run(PhaseSuite.java:203)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:195)
	at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:137)
	at jdk.internal.vm.compiler/org.graalvm.compiler.core.GraalCompiler.emitFrontEnd(GraalCompiler.java:229)
	at jdk.internal.vm.compiler/org.graalvm.compiler.core.GraalCompiler.compile(GraalCompiler.java:172)
	at jdk.internal.vm.compiler/org.graalvm.compiler.core.GraalCompiler.compileGraph(GraalCompiler.java:158)
	at jdk.aot/jdk.tools.jaotc.AOTBackend.compileGraph(AOTBackend.java:141)
	at jdk.aot/jdk.tools.jaotc.AOTBackend.compileMethod(AOTBackend.java:103)
	at jdk.aot/jdk.tools.jaotc.AOTCompilationTask.run(AOTCompilationTask.java:121)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1131)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:631)
	at java.base/java.lang.Thread.run(Thread.java:844)

 failed main([Ljava/lang/String;)V

0 methods compiled, 1 methods failed (103797 ms)
Freeing memory [used: 413.0 MB, comm: 1.8 GB , freeRatio ~= 77.4%] (17 ms)
Parsing compiled code (1 ms)
Freeing memory [used: 6.1 MB , comm: 17.0 MB, freeRatio ~= 64.2%] (22 ms)
Processing metadata (11 ms)
Freeing memory [used: 5.8 MB , comm: 17.0 MB, freeRatio ~= 66.1%] (15 ms)
Preparing stubs binary (0 ms)
Preparing compiled binary (0 ms)
.header: 57 bytes
.config: 40 bytes
.kls.offsets: 0 bytes
.meth.offsets: 0 bytes
.kls.dependencies: 0 bytes
.stubs.offsets: 964 bytes
.meth.metadata: 6792 bytes
.text: 21344 bytes
.code.segments: 165 bytes
.meth.constdata: 29152 bytes
.kls.got: 0 bytes
.cnt.got: 0 bytes
.meta.got: 0 bytes
.meth.state: 320 bytes
.oop.got: 0 bytes
.meta.names: 1874 bytes
Freeing memory [used: 5.8 MB , comm: 17.0 MB, freeRatio ~= 66.1%] (13 ms)
Creating binary: C0 (5 ms)
Freeing memory [used: 5.8 MB , comm: 17.0 MB, freeRatio ~= 66.1%] (15 ms)
Creating shared library: C0.so (3 ms)
Final memory   [used: 5.6 MB , comm: 17.0 MB, freeRatio ~= 66.9%]
Total time: 104757 ms

real	1m44.977s
user	1m56.680s
sys	0m0.444s

[dougxc]

http://mail.openjdk.java.net/pipermail/graal-dev/2018-January/005222.html

[tianxiaogu]

@dougxc , the following program can trigger the NullPointerException (without -J-Xcomp) or crash the JVM (with -J-Xcomp) in about 5 minutes on my Mac.

public class Test {

    public static void M3() {
        M3();
        M3();
        M3();
    }

    public static void main(String[] args) {
        M3();
        M3();
    }
}

Options:

--compile-commands commands-test.txt -J-Dgraal.InlineDuringParsingMaxDepth=10

commands-test.txt

compileOnly Test.main.*

Log:

tianxiaogu@~/Downloads/jasmin-2.4/graal-290 >>> ~/Projects/hs/build/macosx-x86_64-normal-server-release/images/jdk/bin/jaotc --output Test.so  --compile-commands commands-test.txt -J-Dgraal.InlineDuringParsingMaxDepth=10  -J-Xcomp Test.class
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x000000011b2d8ab5, pid=87625, tid=9735
#
# JRE version: OpenJDK Runtime Environment (10.0) (build 10-internal+0-adhoc.tianxiaogu.hs)
# Java VM: OpenJDK 64-Bit Server VM (10-internal+0-adhoc.tianxiaogu.hs, compiled mode, tiered, jvmci, compressed oops, g1 gc, bsd-amd64)
# Problematic frame:
# J 10065 c2 org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Lorg/graalvm/compiler/graph/Node;J)Lorg/graalvm/compiler/graph/NodeList; jdk.internal.vm.compiler@10-internal (12 bytes) @ 0x000000011b2d8ab5 [0x000000011b2d8aa0+0x0000000000000015]
#
# No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /Users/tianxiaogu/Downloads/jasmin-2.4/graal-290/hs_err_pid87625.log
Could not load hsdis-amd64.dylib; library not loadable; PrintAssembly is disabled
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#
Abort trap: 6
tianxiaogu@~/Downloads/jasmin-2.4/graal-290 >>> ~/Projects/hs/build/macosx-x86_64-normal-server-release/images/jdk/bin/jaotc --output Test.so  --compile-commands commands-test.txt -J-Dgraal.InlineDuringParsingMaxDepth=10   Test.class
Error: Failed compilation: Test.main([Ljava/lang/String;)V: java.lang.NullPointerException
tianxiaogu@~/Downloads/jasmin-2.4/graal-290 >>> 

[dougxc]

Thanks for the test. However, it shows a crash on jaotc from the JDK tip. Since the version of Graal in the JDK is only periodically synchronized with the version of Graal in this GitHub repo, reproducing a crash on jaotc doesn't help much in terms of determining if the problem still exists in Graal. For example, https://github.com/oracle/graal/blob/1b0ce5ae917b749fd51b0072dcae21ee1a3c4191/compiler/src/org.graalvm.compiler.core.test/src/org/graalvm/compiler/core/test/TrivialInliningExplosionTest.java captures the same pattern as your sample program above. However, it passes:

dsimon@kruger-4 ~/h/g/compiler> mx unittest TrivialInliningExplosionTest
MxJUnitCore
JUnit version 4.12
.
Time: 3,255

OK (1 test)

To test with larger values of InlineDuringParsingMaxDepth, the 2 assertions at the end of org.graalvm.compiler.core.test.TrivialInliningExplosionTest.test() can be deleted:

dsimon@kruger-4 ~/h/g/compiler> mx unittest -Dgraal.InlineDuringParsingMaxDepth=6 TrivialInliningExplosionTest
MxJUnitCore
JUnit version 4.12
.
Time: 4,627

OK (1 test)

Any larger value of InlineDuringParsingMaxDepth causes a jdk.vm.ci.code.BailoutException: Code installation failed: code is too large on my Mac.

[tianxiaogu]

@dougxc Thanks, Doug. Since an error can also be triggered with the latest publicly available Oracle JDK 9.0.4+11, we may verify this issue later after a stable version of the new JDK is released.

[dougxc]

Ok, great. Please re-open this issue or create a new one at that time.

[vnkozlov]

Doug, what is default value of InlineDuringParsingMaxDepth for recursion? In C2 it is MaxRecursiveInlineLevel=1 (it is separate from normal inlining depth limit).
Do you have flag for it? We may need to set limit for AOT compilation since we don't have profiling information.

[vnkozlov]

I reproduced crash with latest jdk/hs.
I decoded C2 generated code and it failed at the very beginning:

public static NodeList getNodeListUnsafe(Node node, long offset) {
return (NodeList) UNSAFE.getObject(node, offset);
}

Graal uses wrong Unsafe offset (0!!!):

#r018 rsi:rsi : parm 0: org/graalvm/compiler/graph/Node *
#r016 rdx:rdx : parm 1: long

00c movl R11, [RSI + RDX] # compressed ptr
010 testl R11, R11 # compressed ptr
013 je,s B5 P=0.001000 C=-1.000000
015 B2: # B6 B3 <- B1 Freq: 0.999
015 movl R8, [R12 + R11 << 3 + #8] (compressed oop addressing) # compressed klass ptr << crashed here

RSI=0x000000008d9a5a10
RDX=0x0000000000000000

As result instead of field you got Object's markword:
R11=0x000000000000000d

[dougxc]

The default value for InlineDuringParsingMaxDepth is 3. We experimented with a separate recursive inlining limit but it's simpler to just be quite conservative overall with inlining during parsing. If there's real benefit to be had from inlining, then the incremental inliner should make that decision. It could well be that it needs to be adjusted for AOT.

When you reproduced the latest crash with latest jdk/hs, what version of Graal is that using? I'm trying to find out if this is a bug that has been already fixed in github Graal. That's why it's helpful to reproduce with a Graal unit test and not rely on jaotc.

[vnkozlov]

Unfortunately Graal in JDK is relatively old. Last push was on Dec 13:
https://bugs.openjdk.java.net/browse/JDK-8193439

We waited changes for http://ol-jira.us.oracle.com/browse/GR-7679 to be propagated from jdk10 (where it was pushed) into jdk/hs. We how have it here and Igor should update Graal soon. It is tracked by: https://bugs.openjdk.java.net/browse/JDK-8194819

[vnkozlov]

Let me update Graal locally and test with it.

[vnkozlov]

I rebuilt Graal after Igor updated it today and problems still present. Very long compilation time due to inlining of recursion and crash in C2 generated code or exception in Interpreter if disable compilation of method:
jaotc --compile-commands tem3.txt --verbose --output TestM3.so TestM3.class -J-Dgraal.InlineDuringParsingMaxDepth=10 -J-Xcomp -J-XX:CompileCommand=exclude,org.graalvm.compiler.graph.Edges::getNodeListUnsafe -J-XX:CompileCommand=exclude,org.graalvm.compiler.graph.NodeClass$RawEdgesIterator::*
CompileCommand: exclude org/graalvm/compiler/graph/Edges.getNodeListUnsafe
CompileCommand: exclude org/graalvm/compiler/graph/NodeClass$RawEdgesIterator.*
Compiling TestM3.so...
1 classes found (3496 ms)
Scanning TestM3
added main([Ljava/lang/String;)V
3 methods total, 1 methods to compile (516 ms)
Freeing memory [used: 4.0 MB , comm: 8.0 MB , freeRatio ~= 50.0%] (1653 ms)
Compiling with 16 threads
.Error: Failed compilation: TestM3.main([Ljava/lang/String;)V: java.lang.NullPointerException
java.lang.NullPointerException
at jdk.internal.vm.compiler@10-internal/org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Edges.java:71)
at jdk.internal.vm.compiler@10-internal/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.getInput(NodeClass.java:1041)
at jdk.internal.vm.compiler@10-internal/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.forward(NodeClass.java:981)
at jdk.internal.vm.compiler@10-internal/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.hasNext(NodeClass.java:974)
at jdk.internal.vm.compiler@10-internal/org.graalvm.compiler.phases.schedule.SchedulePhase$Instance.processNodes(SchedulePhase.java:888)
...
failed main([Ljava/lang/String;)V

0 methods compiled, 1 methods failed (156672 ms)

[dougxc]

What happens if you omit the -J-Dgraal.InlineDuringParsingMaxDepth=10 option?
The overly long compile time is ok in my opinion - explicitly setting compiler options to something other than their default always runs the risk of suboptimal compilation behavior. That said, we should still not crash when someone explicitly sets that option.

[dougxc]

I've managed to find the root cause of the NPEs/crashes and can reproduce with this unit test:

    @Test
    public void testNodeInputIteratorLimit() {
        DebugContext debug = getDebugContext();
        StructuredGraph graph = new StructuredGraph.Builder(debug.getOptions(), debug, AllowAssumptions.YES).build();

        AbstractMergeNode merge = graph.add(new MergeNode());
        for (int i = 0; i < 65536; i++) {
            EndNode end = graph.add(new EndNode());
            merge.addForwardEnd(end);
        }
        merge.inputs().count();
        EndNode end = graph.add(new EndNode());
        merge.addForwardEnd(end);
        merge.inputs().count();
    }

We will fix it.

[thomaswue]

I think we want to avoid the situation that leads to merge nodes with more than 65536 predecessors.

[dougxc]

I agree which is why we changed the default value of InlineDuringParsingMaxDepth from 10 to 3. That said, we should still not crash if someone explicitly bumps up this number but just bail out instead.

[vnkozlov]

Thank you, Doug. I tested with InlineDuringParsingMaxDepth=3 and it works:
1 methods compiled, 0 methods failed (20889 ms)

Note, ignore time - I am running with fastdebug build. Also with -Xcomp flag slowdown execution too (it enforce -Xbatch).

It is passed too (same time) with omit -Dgraal.InlineDuringParsingMaxDepth