jaotc: unexpected long compile time for a 3012-byte generated class
Tianxiao Gu
tianxiao.gu at gmail.com
Sat Jan 27 09:16:43 UTC 2018
The OpenJDK head still crashes with this program. Now I can manage to
reproduce the crash in about 1 min on my computer. The crash stack trace
is different.
Using the following options to start jaotc.
1. Add options -J-Dgraal.InlineDuringParsingMaxDepth=8 and -J-Xcomp.
2. Add options --compile-commands commands.txt to jaotc, where the contents
of commands.txt is
compileOnly C0.M2.*
If we use CompileCommand to exclude
org.graalvm.compiler.graph.Edges::getNodeListUnsafe, we get a Java stack
trace.
3. Add option
-J-XX:CompileCommand=exclude,org.graalvm.compiler.graph.Edges::getNodeListUnsafe
Summary:
HEAD + Include: VM crashed
HEAD + Exclude: Java Exception
JDK 9.04 + Include: VM crashed
JDK 9.04 + Exclude: VM crashed
I have fired a similar bug report with another program at
https://github.com/oracle/graal/issues/290
So far, we still have no idea whether this is a problem of C2 or Graal.
=== C2 (HEAD) crashes ===
$ time ../../../openjdk/jdk/build/linux-x86_64-normal-server-release/jdk/bin/jaotc
> --output C0.so --verbose -J-Dgraal.InlineDuringParsingMaxDepth=8
> --compile-commands commands.txt -J-Xcomp C0
> Compiling C0.so...
> 1 classes found (721 ms)
> Scanning C0
> added M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/
> Short;Ljava/lang/Float;SLjava/lang/Character;[F)V
> 7 methods total, 1 methods to compile (173 ms)
> Freeing memory [used: 3.7 MB , comm: 10.0 MB, freeRatio ~= 62.6%] (555 ms)
> Compiling with 8 threads
> .#
> # A fatal error has been detected by the Java Runtime Environment:
> #
> # SIGSEGV (0xb) at pc=0x00007f3c74f57135, pid=19884, tid=19921
> #
> # JRE version: OpenJDK Runtime Environment (10.0) (build
> 10-internal+0-adhoc.t.jdk)
> # Java VM: OpenJDK 64-Bit Server VM (10-internal+0-adhoc.t.jdk, compiled
> mode, tiered, jvmci, compressed oops, g1 gc, linux-amd64)
> # Problematic frame:
> # J 10840 c2 org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Lorg/
> graalvm/compiler/graph/Node;J)Lorg/graalvm/compiler/graph/NodeList;
> jdk.internal.vm.compiler (12 bytes) @ 0x00007f3c74f57135
> [0x00007f3c74f57120+0x0000000000000015]
> #
> # 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/old-bugs/0123-old-bugs/jaotc-
> jdk-20180122171043/core.19884)
> #
> # An error report file with more information is saved as:
> # /home/t/Projects/JVMTesting/old-bugs/0123-old-bugs/jaotc-
> jdk-20180122171043/hs_err_pid19884.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 1m14.411s
> user 1m17.352s
> sys 0m0.604s
=== Exclude getNodeListUnsafe ===
$ time
> ../../../openjdk/jdk/build/linux-x86_64-normal-server-release/jdk/bin/jaotc
> --output C0.so --verbose -J-Dgraal.InlineDuringParsingMaxDepth=8
> --compile-commands commands.txt -J-Xcomp
> -J-XX:CompileCommand=exclude,org.graalvm.compiler.graph.Edges::getNodeListUnsafe
> C0
> CompileCommand: exclude org/graalvm/compiler/graph/Edges.getNodeListUnsafe
> Compiling C0.so...
> 1 classes found (704 ms)
> Scanning C0
> added
> M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/Short;Ljava/lang/Float;SLjava/lang/Character;[F)V
> 7 methods total, 1 methods to compile (130 ms)
> Freeing memory [used: 4.6 MB , comm: 10.0 MB, freeRatio ~= 54.2%] (792 ms)
> Compiling with 8 threads
> .Error: Failed compilation:
> C0.M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/Short;Ljava/lang/Float;SLjava/lang/Character;[F)V:
> java.lang.NullPointerException
> java.lang.NullPointerException
> at
> jdk.internal.vm.compiler/org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Edges.java:71)
> at
> jdk.internal.vm.compiler/org.graalvm.compiler.graph.NodeClass$RawEdgesIterator.getInput(NodeClass.java:1041)
> 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
> M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/Short;Ljava/lang/Float;SLjava/lang/Character;[F)V
> 0 methods compiled, 1 methods failed (80228 ms)
> Freeing memory [used: 430.5 MB, comm: 627.0 MB, freeRatio ~= 31.3%] (22 ms)
> Parsing compiled code (3 ms)
> Freeing memory [used: 9.8 MB , comm: 24.0 MB, freeRatio ~= 59.0%] (20 ms)
> Processing metadata (146 ms)
> Freeing memory [used: 6.1 MB , comm: 24.0 MB, freeRatio ~= 74.7%] (20 ms)
> Preparing stubs binary (3 ms)
> Preparing compiled binary (1 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: 6.1 MB , comm: 24.0 MB, freeRatio ~= 74.7%] (20 ms)
> Creating binary: C0 (74 ms)
> Freeing memory [used: 6.1 MB , comm: 24.0 MB, freeRatio ~= 74.7%] (20 ms)
> Creating shared library: C0.so (13 ms)
> Final memory [used: 5.9 MB , comm: 24.0 MB, freeRatio ~= 75.3%]
> Total time: 90239 ms
> real 1m32.837s
> user 1m36.420s
> sys 0m0.792s
================================================================================
The crash is *more* easily to be reproduced in Oracle JDK 9.0.4+11 (without
-J-Xcomp)
>
> $ time ../../../jdk-9.0.4/bin/jaotc --output C0.so --verbose -J-Dgraal.InlineDuringParsingMaxDepth=8
> --compile-commands commands.txt C0
> Compiling C0...
> 1 classes found (451 ms)
> Scanning C0
> added M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/
> Short;Ljava/lang/Float;SLjava/lang/Character;[F)V
> 7 methods total, 1 methods to compile (95 ms)
> Freeing memory [used: 2.5 MB , comm: 8.0 MB , freeRatio ~= 68.7%] (803 ms)
> Compiling with 8 threads
> .#
> # A fatal error has been detected by the Java Runtime Environment:
> #
> # SIGSEGV (0xb) at pc=0x00007f43717c8d35, pid=20015, tid=20049
> #
> # 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, compiled mode,
> tiered, jvmci, compressed oops, g1 gc, linux-amd64)
> # Problematic frame:
> # J 9702 c2 org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Lorg/
> graalvm/compiler/graph/Node;J)Lorg/graalvm/compiler/graph/NodeList;
> jdk.internal.vm.compiler at 9.0.4 (12 bytes) @ 0x00007f43717c8d35
> [0x00007f43717c8d20+0x0000000000000015]
> #
> # 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/old-bugs/0123-old-bugs/jaotc-
> jdk-20180122171043/core.20015)
> #
> # An error report file with more information is saved as:
> # /home/t/Projects/JVMTesting/old-bugs/0123-old-bugs/jaotc-
> jdk-20180122171043/hs_err_pid20015.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 1m17.911s
> user 1m25.256s
> sys 0m0.896s
=== Exclude getNodeListUnsafe ===
time ../../../jdk-9.0.4/bin/jaotc --output C0.so --verbose
> -J-Dgraal.InlineDuringParsingMaxDepth=8 --compile-commands commands.txt
> -J-XX:CompileCommand=exclude,org.graalvm.compiler.graph.Edges::getNodeListUnsafe
> C0
> CompileCommand: exclude org/graalvm/compiler/graph/Edges.getNodeListUnsafe
> Compiling C0...
> 1 classes found (17 ms)
> Scanning C0
> added
> M2([C[SLjava/lang/Number;Ljava/lang/Number;Ljava/lang/Short;Ljava/lang/Float;SLjava/lang/Character;[F)V
> 7 methods total, 1 methods to compile (4 ms)
> Freeing memory [used: 2.1 MB , comm: 8.0 MB , freeRatio ~= 73.6%] (20 ms)
> Compiling with 8 threads
> .#
> # A fatal error has been detected by the Java Runtime Environment:
> #
> # SIGSEGV (0xb) at pc=0x00007ff051b6ab29, pid=20922, tid=20956
> #
> # 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 org.graalvm.compiler.graph.Edges.getNodeListUnsafe(Lorg/graalvm/compiler/graph/Node;J)Lorg/graalvm/compiler/graph/NodeList;+5
> jdk.internal.vm.compiler at 9.0.4
> #
> # 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/old-bugs/0123-old-bugs/jaotc-jdk-20180122171043/core.20922)
> #
> # An error report file with more information is saved as:
> #
> /home/t/Projects/JVMTesting/old-bugs/0123-old-bugs/jaotc-jdk-20180122171043/hs_err_pid20922.log
> Compiled method (c1) 65364 1005 1 sun.misc.Unsafe::getObject
> (9 bytes)
> total in heap [0x00007ff05965cb90,0x00007ff05965cee0] = 848
> relocation [0x00007ff05965cd00,0x00007ff05965cd28] = 40
> main code [0x00007ff05965cd40,0x00007ff05965ce20] = 224
> stub code [0x00007ff05965ce20,0x00007ff05965ceb0] = 144
> scopes data [0x00007ff05965ceb0,0x00007ff05965ceb8] = 8
> scopes pcs [0x00007ff05965ceb8,0x00007ff05965ced8] = 32
> dependencies [0x00007ff05965ced8,0x00007ff05965cee0] = 8
> 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 1m5.467s
> user 1m21.900s
> sys 0m0.444s
On Wed, Jan 24, 2018 at 12:04 PM, Tianxiao Gu <tianxiao.gu at gmail.com> wrote:
> Thanks, Doug.
>
> I agree with you. The fatal error indicates that the C2 compiler may
> generate problematic code for a method (see below) of graal, when graal
> itself has been driven to a crazy state by the input C0.class.
> I will file an issue with another class that does not end with a fatal
> error of the runtime but still leads to a long compile time.
>
> Stack: [0x00007f29a22c2000,0x00007f29a23c3000], sp=0x00007f29a23c06d0, free space=1017k
> Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
> J 3623% c2 org.graalvm.compiler.phases.schedule.SchedulePhase$Instance.scheduleEarliestIterative(Lorg/graalvm/compiler/core/common/cfg/BlockMap;Lorg/graalvm/compiler/graph/NodeMap;Lorg/graalvm/compiler/graph/NodeBitMap;Lorg/graalvm/compiler/nodes/StructuredGraph;Z)V jdk.internal.vm.compiler (999 bytes) @ 0x00007f2a04f371a2 [0x00007f2a04f368e0+0x00000000000008c2]
> j
>
>
> On Wed, Jan 24, 2018 at 3:02 AM, Doug Simon <doug.simon at oracle.com> wrote:
>
>> Hi Tianxiao,
>>
>> As far as I'm aware, Graal compiled code does not run during jaotc so I
>> don't think the crash is Graal related. It's in a C2 compiled method.
>>
>> That said, the long compile time is almost certainly some issue in Graal.
>> Looking at the class file, it seems like some inlining maybe be going crazy
>> on the infinitely recursive C0.M0() method and I can confirm this with:
>>
>> jaotc -J-Dgraal.TraceInlineDuringParsing=true C0.class
>>
>> Can you please file an issue at https://github.com/oracle/graal/issues
>> and we will investigate further.
>>
>> -Doug
>>
>> > On 24 Jan 2018, at 09:00, Tianxiao Gu <tianxiao.gu at gmail.com> wrote:
>> >
>> > Hi All,
>> >
>> > I found some abnormal behavior of jaotc. It takes 23 minutes for jaotc
>> (head) to compile a 3012-byte generated class file (C0.class)
>> > and jaotc ends with a fatal error. I have managed to reproduce this
>> issue on my machine for 4 times.
>> >
>> > Related files are hosted on Google Drive:
>> >
>> > https://drive.google.com/open?id=1u9O3uPkvucX6PWQkMFER3NAUWIR_KglE
>> >
>> > Reproducing Steps:
>> >
>> > jaotc --output C0.so C0.class
>> >
>> > Environment:
>> >
>> > `java --version`
>> >
>> > openjdk 10-internal 2018-03-20
>> > OpenJDK Runtime Environment (build 10-internal+0-adhoc.t.jdk)
>> > OpenJDK 64-Bit Server VM (build 10-internal+0-adhoc.t.jdk, mixed mode)
>> >
>> > `lscpu`
>> >
>> > Architecture: x86_64
>> > CPU op-mode(s): 32-bit, 64-bit
>> > Byte Order: Little Endian
>> > CPU(s): 8
>> > On-line CPU(s) list: 0-7
>> > Thread(s) per core: 2
>> > Core(s) per socket: 4
>> > Socket(s): 1
>> > NUMA node(s): 1
>> > Vendor ID: GenuineIntel
>> > CPU family: 6
>> > Model: 158
>> > Model name: Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz
>> > Stepping: 9
>> > CPU MHz: 900.000
>> > CPU max MHz: 4200.0000
>> > CPU min MHz: 800.0000
>> > BogoMIPS: 7200.00
>> > Virtualization: VT-x
>> > L1d cache: 32K
>> > L1i cache: 32K
>> > L2 cache: 256K
>> > L3 cache: 8192K
>> > NUMA node0 CPU(s): 0-7
>> > Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr
>> pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe
>> syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts
>> rep_good nopl xtopology nonstop_tsc aperfmperf tsc_known_freq pni pclmulqdq
>> dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid
>> sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c
>> rdrand lahf_lm abm 3dnowprefetch epb intel_pt tpr_shadow vnmi flexpriority
>> ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx
>> rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat
>> pln pts hwp hwp_notify hwp_act_window hwp_epp
>> >
>> > `uname -a`
>> >
>> > Linux xtiger 4.10.0-42-generic #46~16.04.1-Ubuntu SMP Mon Dec 4
>> 15:57:59 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-compiler-dev/attachments/20180127/1e706b3f/attachment-0001.html>
More information about the hotspot-compiler-dev
mailing list