United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
JDK-8022585 : JVM crashes when ran with -XX:+PrintInlining

Details
Type:
Bug
Submit Date:
2013-08-06
Status:
Closed
Updated Date:
2014-06-05
Project Name:
JDK
Resolved Date:
2013-09-25
Component:
hotspot
OS:
windows_8,linux
Sub-Component:
compiler
CPU:
Priority:
P3
Resolution:
Fixed
Affected Versions:
7u40
Fixed Versions:
7u60 (b01)

Related Reports
Backport:
Backport:
Backport:
Duplicate:
Duplicate:
Duplicate:
Relates:
Relates:

Sub Tasks

Description
FULL PRODUCT VERSION :
C:\Users\sixi> " c:\Program Files\Java\jdk1.7.0_40\bin\java.exe "  -version
java version  " 1.7.0_40-ea " 
Java(TM) SE Runtime Environment (build 1.7.0_40-ea-b36)
Java HotSpot(TM) 64-Bit Server VM (build 24.0-b55, mixed mode)

FULL OS VERSION :
C:\Users\sixi>ver

Microsoft Windows [Version 6.2.9200]

EXTRA RELEVANT SYSTEM CONFIGURATION :
Windows 8 is running inside an OS that is running on a physycal machine.

i got the same error on a vm running linux also, but NOT with the stripped java file that i am providing with this report (running linux 64bit version of the same jdk - Linux matilda 3.2.0-51-generic #77-Ubuntu SMP Wed Jul 24 20:18:19 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux)

A DESCRIPTION OF THE PROBLEM :
application crashes shortly after startup.
Apparently C2 compiler crashes

THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: No

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
start provider app with the parameters
java -server -Xms128M -Xmx128M -XX:+PrintCommandLineFlags -XX:+AggressiveOpts -XX:+AggressiveHeap -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining -cp . ro.derbederos.hlfe.parser.Benchmark

EXPECTED VERSUS ACTUAL BEHAVIOR :
application should end up normally after 5-10 secs but it crashes with
 Error: ShouldNotReachHere().

Apparently on linux box the C2 compiler is not triggered on the example. I think On stack replacement doesn;t take place and execution takes ~30 secs instead of 5 like on windows box.

on windows box PrintCommandLineFlags  option reveals a parameter which does not appear as set on the linux box:
-XX:-UseLargePagesIndividualAllocation

also as you see below on windows box there is a line saying:
#  Internal Error (opto/compile.hpp:420)
on linux box, when i get the error, it states compile:hpp:420 without the  " opto/ "   string in front of it.

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (opto/compile.hpp:420), pid=4908, tid=5472
#  Error: ShouldNotReachHere()
#
# JRE version: Java(TM) SE Runtime Environment (7.0_40-b36) (build 1.7.0_40-ea-b36)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.0-b55 mixed mode windows-amd64 compressed oops)
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# An error report file with more information is saved as:
# C:\Users\sixi\javaProjects\hlfe.hg\hs_err_pid4908.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.sun.com/bugreport/crash.jsp
#
ERROR MESSAGES/STACK TRACES THAT OCCUR :
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (opto/compile.hpp:420), pid=4908, tid=5472
#  Error: ShouldNotReachHere()
#
# JRE version: Java(TM) SE Runtime Environment (7.0_40-b36) (build 1.7.0_40-ea-b36)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.0-b55 mixed mode windows-amd64 compressed oops)
# Failed to write core dump. Minidumps are not enabled by default on client versions of Windows
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.sun.com/bugreport/crash.jsp
#

---------------  T H R E A D  ---------------

Current thread (0x000000000306b800):  JavaThread  " C2 CompilerThread1 "  daemon [_thread_in_native, id=5472, stack(0x0000000009950000,0x0000000009a50000)]

Stack: [0x0000000009950000,0x0000000009a50000]

Current CompileTask:
C2:    302    5             ro.derbederos.hlfe.parser.Benchmark::bench (100 bytes)


---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
  0x000000000306d000 JavaThread  " Service Thread "  daemon [_thread_blocked, id=4560, stack(0x0000000009a50000,0x0000000009b50000)]
=>0x000000000306b800 JavaThread  " C2 CompilerThread1 "  daemon [_thread_in_native, id=5472, stack(0x0000000009950000,0x0000000009a50000)]
  0x0000000003061000 JavaThread  " C2 CompilerThread0 "  daemon [_thread_blocked, id=4756, stack(0x0000000009850000,0x0000000009950000)]
  0x000000000305e000 JavaThread  " Attach Listener "  daemon [_thread_blocked, id=4460, stack(0x0000000009750000,0x0000000009850000)]
  0x0000000003059000 JavaThread  " Signal Dispatcher "  daemon [_thread_blocked, id=2276, stack(0x0000000009650000,0x0000000009750000)]
  0x000000000728f800 JavaThread  " Finalizer "  daemon [_thread_blocked, id=4012, stack(0x0000000009150000,0x0000000009250000)]
  0x0000000007289000 JavaThread  " Reference Handler "  daemon [_thread_blocked, id=6108, stack(0x0000000009050000,0x0000000009150000)]
  0x0000000002f70800 JavaThread  " main "  [_thread_in_Java, id=2904, stack(0x0000000002d60000,0x0000000002e60000)]

Other Threads:
  0x0000000007283800 VMThread [stack: 0x0000000008f50000,0x0000000009050000] [id=44]
  0x000000000306e800 WatcherThread [stack: 0x0000000009b50000,0x0000000009c50000] [id=5448]

VM state:not at safepoint (normal execution)

VM Mutex/Monitor currently owned by a thread: None

Heap
 PSYoungGen      total 43008K, used 512K [0x00000000fd000000, 0x0000000100000000, 0x0000000100000000)
  eden space 36864K, 1% used [0x00000000fd000000,0x00000000fd0801a0,0x00000000ff400000)
  from space 6144K, 0% used [0x00000000ffa00000,0x00000000ffa00000,0x0000000100000000)
  to   space 6144K, 0% used [0x00000000ff400000,0x00000000ff400000,0x00000000ffa00000)
 ParOldGen       total 81920K, used 0K [0x00000000f8000000, 0x00000000fd000000, 0x00000000fd000000)
  object space 81920K, 0% used [0x00000000f8000000,0x00000000f8000000,0x00000000fd000000)
 PSPermGen       total 21504K, used 2426K [0x00000000f2e00000, 0x00000000f4300000, 0x00000000f8000000)
  object space 21504K, 11% used [0x00000000f2e00000,0x00000000f305e980,0x00000000f4300000)

Card table byte_map: [0x0000000006130000,0x00000000061a0000] byte_map_base: 0x0000000005999000

Polling page: 0x0000000000eb0000

Code Cache  [0x0000000003070000, 0x00000000032e0000, 0x0000000006070000)
 total_blobs=185 nmethods=4 adapters=134 free_code_cache=48766Kb largest_free_block=49921984

Compilation events (7 events):
Event: 0.065 Thread 0x0000000003061000    2             ro.derbederos.hlfe.parser.Benchmark$1::processData (31 bytes)
Event: 0.070 Thread 0x0000000003061000 nmethod 2 0x00000000030d0d50 code [0x00000000030d0e80, 0x00000000030d0f18]
Event: 0.076 Thread 0x000000000306b800    3             ro.derbederos.hlfe.parser.Benchmark$1::processData (9 bytes)
Event: 0.077 Thread 0x000000000306b800 nmethod 3 0x00000000030d0a90 code [0x00000000030d0bc0, 0x00000000030d0c78]
Event: 0.080 Thread 0x0000000003061000    4 %           ro.derbederos.hlfe.parser.Benchmark::bench @ 60 (100 bytes)
Event: 0.082 Thread 0x0000000003061000 nmethod 4% 0x00000000030d1f90 code [0x00000000030d2100, 0x00000000030d2318]
Event: 0.301 Thread 0x000000000306b800    5             ro.derbederos.hlfe.parser.Benchmark::bench (100 bytes)

GC Heap History (0 events):
No events

Deoptimization events (0 events):
No events

Internal exceptions (4 events):
Event: 0.028 Thread 0x0000000002f70800 Threw 0x00000000fd010838 at C:\jdk7u2_64p\jdk7u40\hotspot\src\share\vm\prims\jni.cpp:3991
Event: 0.058 Thread 0x0000000002f70800 Threw 0x00000000fd052600 at C:\jdk7u2_64p\jdk7u40\hotspot\src\share\vm\prims\jvm.cpp:1244
Event: 0.062 Thread 0x0000000002f70800 Threw 0x00000000fd058ae8 at C:\jdk7u2_64p\jdk7u40\hotspot\src\share\vm\prims\jvm.cpp:1244
Event: 0.063 Thread 0x0000000002f70800 Threw 0x00000000fd05a690 at C:\jdk7u2_64p\jdk7u40\hotspot\src\share\vm\prims\jvm.cpp:1244

Events (10 events):
Event: 0.062 loading class 0x0000000003016830
Event: 0.062 loading class 0x0000000003016830 done
Event: 0.062 loading class 0x0000000002fe5cf0
Event: 0.062 loading class 0x0000000002fe5cf0 done
Event: 0.062 loading class 0x0000000007284a10
Event: 0.062 loading class 0x0000000007284a10 done
Event: 0.063 loading class 0x0000000002fcd170
Event: 0.063 loading class 0x0000000002fcd170 done
Event: 0.063 loading class 0x000000000306da00
Event: 0.063 loading class 0x000000000306da00 done


Dynamic libraries:
0x000007f660790000 - 0x000007f6607c3000 C:\Program Files\Java\jdk1.7.0_40\bin\javaw.exe
0x000007ff6c780000 - 0x000007ff6c940000 C:\WINDOWS\SYSTEM32
tdll.dll
0x000007ff6b950000 - 0x000007ff6ba86000 C:\WINDOWS\system32\KERNEL32.DLL
0x000007ff69a60000 - 0x000007ff69b53000 C:\WINDOWS\system32\KERNELBASE.dll
0x000007ff6c4d0000 - 0x000007ff6c5ae000 C:\WINDOWS\system32\ADVAPI32.dll
0x000007ff6c120000 - 0x000007ff6c26c000 C:\WINDOWS\system32\USER32.dll
0x000007ff67190000 - 0x000007ff673fa000 C:\WINDOWS\WinSxS\amd64_microsoft.windows.common-controls_6595b64144ccf1df_6.0.9200.16579_none_418ab7ef718b27ef\COMCTL32.dll
0x000007ff6bd00000 - 0x000007ff6bda5000 C:\WINDOWS\system32\msvcrt.dll
0x000007ff6b820000 - 0x000007ff6b868000 C:\WINDOWS\SYSTEM32\sechost.dll
0x000007ff6bbb0000 - 0x000007ff6bcf0000 C:\WINDOWS\system32\RPCRT4.dll
0x000007ff6c630000 - 0x000007ff6c771000 C:\WINDOWS\system32\GDI32.dll
0x000007ff6b560000 - 0x000007ff6b599000 C:\WINDOWS\system32\IMM32.DLL
0x000007ff6bdb0000 - 0x000007ff6bec5000 C:\WINDOWS\system32\MSCTF.dll
0x000007ff695c0000 - 0x000007ff69606000 C:\Windows\system32
vinitx.dll
0x000000000f000000 - 0x000000000f006000 C:\Program Files\NVIDIA Corporation\CoProcManager\detoured.dll
0x000007ff67130000 - 0x000007ff67185000 C:\Program Files\NVIDIA Corporation\CoProcManager
vd3d9wrapx.dll
0x000007ff6b5a0000 - 0x000007ff6b770000 C:\WINDOWS\system32\SETUPAPI.dll
0x000007ff698d0000 - 0x000007ff6991f000 C:\WINDOWS\system32\CFGMGR32.dll
0x000007ff69920000 - 0x000007ff69942000 C:\WINDOWS\system32\DEVOBJ.dll
0x000007ff670c0000 - 0x000007ff670fd000 C:\Program Files\NVIDIA Corporation\CoProcManager
vdxgiwrapx.dll
0x000000005a490000 - 0x000000005a561000 C:\Program Files\Java\jdk1.7.0_40\jre\bin\msvcr100.dll
0x0000000059680000 - 0x0000000059e49000 C:\Program Files\Java\jdk1.7.0_40\jre\bin\server\jvm.dll
0x000007ff61cb0000 - 0x000007ff61cb9000 C:\WINDOWS\SYSTEM32\WSOCK32.dll
0x000007ff66ae0000 - 0x000007ff66b00000 C:\WINDOWS\SYSTEM32\WINMM.dll
0x000007ff6bcf0000 - 0x000007ff6bcf7000 C:\WINDOWS\system32\PSAPI.DLL
0x000007ff6c5d0000 - 0x000007ff6c628000 C:\WINDOWS\system32\WS2_32.dll
0x000007ff669e0000 - 0x000007ff66a12000 C:\WINDOWS\SYSTEM32\WINMMBASE.dll
0x000007ff6c4c0000 - 0x000007ff6c4c9000 C:\WINDOWS\system32\NSI.dll
0x000000005a480000 - 0x000000005a48f000 C:\Program Files\Java\jdk1.7.0_40\jre\bin\verify.dll
0x000000005a450000 - 0x000000005a478000 C:\Program Files\Java\jdk1.7.0_40\jre\bin\java.dll
0x000000005a430000 - 0x000000005a445000 C:\Program Files\Java\jdk1.7.0_40\jre\bin\zip.dll

VM Arguments:
jvm_args: -Xms128M -Xmx128M -XX:+PrintCommandLineFlags -XX:+AggressiveOpts -XX:+AggressiveHeap -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining -Dfile.encoding=UTF-8 -Xbootclasspath:C:\Program Files\Java\jdk1.7.0_40\jre\lib\resources.jar;C:\Program Files\Java\jdk1.7.0_40\jre\lib\rt.jar;C:\Program Files\Java\jdk1.7.0_40\jre\lib\jsse.jar;C:\Program Files\Java\jdk1.7.0_40\jre\lib\jce.jar;C:\Program Files\Java\jdk1.7.0_40\jre\lib\charsets.jar;C:\Program Files\Java\jdk1.7.0_40\jre\lib\jfr.jar;C:\Program Files\Java\jdk1.7.0_40\lib\tools.jar
java_command: ro.derbederos.hlfe.parser.Benchmark
Launcher Type: SUN_STANDARD

Environment Variables:
JAVA_HOME=c:\program files\java\jdk1.7.0_25
PATH=C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Program Files (x86)\Common Files\Roxio Shared\OEM\DLLShared\;C:\Program Files (x86)\Common Files\Roxio Shared\OEM\12.0\DLLShared\;C:\Program Files (x86)\Roxio\OEM\AudioCore\;C:\Program Files\Microsoft Windows Performance Toolkit\;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\Program Files\TortoiseHg\;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Intel\OpenCL SDK\2.0\bin\x86;C:\Program Files (x86)\Intel\OpenCL SDK\2.0\bin\x64;C:\appz\apache-maven-3.1.0\bin;c:\jruby-1.7.4\bin;.;;.;
USERNAME=sixi
OS=Windows_NT
PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 42 Stepping 7, GenuineIntel



---------------  S Y S T E M  ---------------

OS: Windows 8 , 64 bit Build 9200

CPU:total 8 (4 cores per cpu, 2 threads per core) family 6 model 42 stepping 7, cmov, cx8, fxsr, mmx, sse, sse2, sse3, ssse3, sse4.1, sse4.2, popcnt, avx, aes, ht, tsc, tscinvbit

Memory: 4k page, physical 8280232k(5493228k free), swap 16668840k(13507420k free)

vm_info: Java HotSpot(TM) 64-Bit Server VM (24.0-b55) for windows-amd64 JRE (1.7.0_40-ea-b36), built on Jul 31 2013 19:30:59 by  " java_re "  with unknown MS VC++:1600

time: Wed Aug 07 00:16:40 2013
elapsed time: 0 seconds


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
package ro.derbederos.hlfe.parser;

public class Benchmark {

    private static double bench(IMyMessageParser parser) {
        String s1 =  " Name=Alice\u0001 " ;
        String s2 =  " Name=Bob\u0001 " ;
        String s3 =  " Name=Carl\u0001 " ;
        String s4 =  " Name=Diane\u0001 " ;
        byte[] s5bytes = (s1 + s2 + s3 + s4).getBytes();

        int numberofmessages = 1000000;
        long t11 = System.nanoTime();
        for (int i = 0; i < numberofmessages / 4; i++) {
            parser.processData(s5bytes);
        }
        long t22 = System.nanoTime();
        return (t22 - t11) / numberofmessages / 1000d;
    }

    public static interface IMyMessageParser {
        public void processData(byte[] buffer);

        public void processData(byte[] buffer, int off, int len);
    }

    public static void main(String[] args) {
        IMyMessageParser parserNew = new IMyMessageParser() {

            @Override
            public void processData(byte[] buffer) {
                processData(buffer, 0, buffer.length);
            }

            @Override
            public void processData(byte[] buffer, int off, int len) {
                long x = System.nanoTime();
                long i = 0;
                while (System.nanoTime() - x < 700) {
                    i++;
                }
                // System.out.println(i);
            }

        };

        int rounds = 20;
        double aNew = 0;
        double timesNew[] = new double[rounds];
        for (int i = -2; i < rounds; i++) {
            double timePerMessage = bench(parserNew);
            if (i < 0)
                continue;
            timesNew[i] = timePerMessage;
        }

        for (int i = 0; i < rounds; i++) {
            System.out.println( " Round:  "  + i);
            System.out.println( " New parser " );
            double timePerMessage = timesNew[i];
            aNew += timePerMessage;
            System.out.println( " Parsing took(wall clock \u03BCs/msg): "  + timePerMessage);
            System.out.println( " New Parser Avg:  "  + aNew / (i + 1));
        }
    }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
workaround is to remove -XX:+PrintInlining
                                    

Comments
URL:   http://hg.openjdk.java.net/hsx/jdk7u/hotspot/rev/68ae51f39b18
User:  kvn
Date:  2013-09-25 04:24:51 +0000

                                     
2013-09-25
You can reproduce the problem simply with -Xcomp:

java -Xcomp -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining t

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (compile.hpp:420), pid=614, tid=61
#  Error: ShouldNotReachHere()
#
# JRE version: Java(TM) SE Runtime Environment (7.0_40-b43) (build 1.7.0_40-b43)
# Java VM: Java HotSpot(TM) Server VM (24.0-b56 compiled mode solaris-x86 )

                                     
2013-09-24
It is blocker for my investigation of P2 8024830 bug. I need to find inlining to reproduce the failure and I can't because of this bug! Roland, how difficult is to fix it?
                                     
2013-09-20
It is only jdk7u40/hs24 problem, it is explained in 8019313 bug description (GrowableArray::at() different declaration). It has also proposed fix (not complete).

http://cr.openjdk.java.net/~goetz/webrevs/fix_inline_trace/

I would prefer to see common fix (use adr_at()) in jdk8 and jdk7. And it fixed my problem for 8024830.

--- a/src/share/vm/opto/compile.cpp	Mon Aug 26 12:06:09 2013 -0700
+++ b/src/share/vm/opto/compile.cpp	Fri Sep 20 14:33:49 2013 -0700
@@ -3534,7 +3534,7 @@
       }
     }
     for (int i = 0; i < _print_inlining_list->length(); i++) {
-      tty->print(_print_inlining_list->at(i).ss()->as_string());
+      tty->print(_print_inlining_list->adr_at(i)->ss()->as_string());
     }
   }
 }
diff -r 1f114331df92 src/share/vm/opto/compile.hpp
--- a/src/share/vm/opto/compile.hpp	Mon Aug 26 12:06:09 2013 -0700
+++ b/src/share/vm/opto/compile.hpp	Fri Sep 20 14:33:49 2013 -0700
@@ -396,12 +396,12 @@
  public:
 
   outputStream* print_inlining_stream() const {
-    return _print_inlining_list->at(_print_inlining).ss();
+    return _print_inlining_list->adr_at(_print_inlining)->ss();
   }
 
   void print_inlining_skip(CallGenerator* cg) {
     if (PrintInlining) {
-      _print_inlining_list->at(_print_inlining).set_cg(cg);
+      _print_inlining_list->adr_at(_print_inlining)->set_cg(cg);
       _print_inlining++;
       _print_inlining_list->insert_before(_print_inlining, PrintInliningBuffer());
     }
@@ -410,10 +410,10 @@
   void print_inlining_insert(CallGenerator* cg) {
     if (PrintInlining) {
       for (int i = 0; i < _print_inlining_list->length(); i++) {
-        if (_print_inlining_list->at(i).cg() == cg) {
+        if (_print_inlining_list->adr_at(i)->cg() == cg) {
           _print_inlining_list->insert_before(i+1, PrintInliningBuffer());
           _print_inlining = i+1;
-          _print_inlining_list->at(i).set_cg(NULL);
+          _print_inlining_list->adr_at(i)->set_cg(NULL);
           return;
         }
       }


                                     
2013-09-20
SQE is ok to defer from 7u40
                                     
2013-08-09
7u40-defer-request Justification:  There is a workaround (remove PrintInlining) and the flag is meant for debugging which is less critical for production use.  
                                     
2013-08-08



Hardware and Software, Engineered to Work Together