7 Replies Latest reply on Jun 17, 2013 7:47 PM by jschellSomeoneStoleMyAlias

    Intermittent JVM crashes with JVM 1.6.0_27


      In our DB we support writing triggers and stored procedures using Java. And for that we use JNI interface. Currently, we are facing an issue where our database process crashes intermittently due to JVM crash. This happens on Solaris 64 Sparc machine. Sometimes, test takes more than few hours to get the JVM crash and sometimes it just takes few minutes. My test script just executes the INSERT statement which fires the trigger execution (i.e java code) in a big loop.

      All of the stack traces of crash showed that JVM is crashed (crash is in libjvm.so), and of them most shows that it got SEGV in interpreterruntime::new_array. I am adding few trace files to this thread. Few of the stack traces are captured from dbx debugger.

      We did not observe any crashes when we changed the jvm to 1.5.0_11 from 1.6.0_27 version of JDK. Also, we tried with later versions of JDK, and the problem still persist. Later versions which we have tried are 1.7.0_05 and 1.7.0_07.

      Following are the details about Java and OS:

      Java version:
      solaris64:sql:110$ java -version
      java version "1.6.0_27"
      Java(TM) SE Runtime Environment (build 1.6.0_27-b07)
      Java HotSpot(TM) 64-Bit Server VM (build 20.2-b06, mixed mode)

      solaris64:sql:110$ cat /etc/*rele*
      Oracle Solaris 10 9/10 s10s_u9wos_14a SPARC
      Copyright (c) 2010, Oracle and/or its affiliates. All rights reserved.
      Assembled 11 August 2010

      solaris64:sql:110$ uname -a
      SunOS oesoldev2 5.10 Generic_142909-17 sun4v sparc sun4v

      solaris64:112$ uname -X
      System = SunOS
      Node = oesoldev2
      Release = 5.10
      KernelID = Generic_142909-17
      Machine = sun4v
      BusType = <unknown>
      Serial = <unknown>
      Users = <unknown>
      OEM# = 0
      Origin# = 1
      NumCPU = 24

      Log File:
      There is no error log is generated. We have a write permission to the directory where process is running. Just to make sure, we have specified different location for the log file (using –XX:ErrorFile), still it did not generate any log file. We also tried to get the heap dump using –XX option (HeapDumpFile), but did not succeed in that too.

      We have also tried increasing JVM Heap Size (-Xmx), Stack size (-Xss) and tried disabling and enabling few JVM options (which are introduced in 1.6) but there is no luck.
      Couple of Stack traces:

      1. Current function is JNIEnv_::CallVoidMethod
      1036 functions->CallVoidMethodV(this,obj,methodID,args);
      (dbx) where
      current thread: t@566
      [1] InterpreterRuntime::newarray(0x101843000, 0x63000, 0x300, 0xffffffff7c400000, 0x10184300, 0xffffffff7c40a000), at 0xffffffff7b97221c
      [2] 0xffffffff76016a54(0x1b, 0xb8, 0x0, 0xffffffff76010540, 0x10184300, 0xffffffff7d7f15c1), at 0xffffffff76016a54
      [3] 0xffffffff76005e60(0xffffffff354064a8, 0xb7, 0x0, 0xffffffff76016180, 0xffffffff3546a010, 0xffffffff7d7f16d1), at 0xffffffff76005e60
      [4] 0xffffffff76005fdc(0xffffffff35406408, 0x108, 0x0, 0xffffffff76016020, 0xffffffff3546a010, 0xffffffff7d7f17e1), at 0xffffffff76005fdc
      [5] 0xffffffff76005e60(0x101843000, 0x7a400, 0x0, 0xffffffff76018a00, 0xffffffff38e600b0, 0xffffffff7d7f18f1), at 0xffffffff76005e60
      [6] 0xffffffff7600024c(0xffffffff7d7f22f0, 0xffffffff7d7f2698, 0xa, 0xfffffffeb06ca900, 0xffffffff7600be40, 0xffffffff7d7f2538), at 0xffffffff7600024c
      [7] JavaCalls::call_helper(0x3, 0x101843000, 0xffffffff7d7f2518, 0xa, 0xffffffff760001e0, 0xffffffff7d7f22c0), at 0xffffffff7b9d6348
      [8] JavaCalls::call(0xffffffff7d7f2690, 0x101843b70, 0xffffffff7d7f2518, 0x101843000, 0xa33c00, 0xa294f4), at 0xffffffff7b9e0b3c
      [9] jni_invoke_nonstatic(0xfffffffeb06ca900, 0xffffffff7d7f2690, 0x101843b70, 0x101843730, 0x101843b18, 0xffffffff7d7f2660), at 0xffffffff7ba0bae0
      [10] jni_CallVoidMethodV(0x1018431d0, 0xffffffff7d7f3268, 0xffffffff7c478b80, 0xffffffff7d7f2838, 0x101843000, 0xffffffff7c46d3e8), at 0xffffffff7be120dc
      =>[11] JNIEnv_::CallVoidMethod(this = 0x1018431d0, obj = 0xffffffff7d7f3268, methodID = 0x101905f38, ...), line 1036 in "jni.h"
      [12] Java_com_progress_sql_sp_SQLDA_fromC(env = 0x1018431d0, jsqlda_obj = 0xffffffff7d7f3268, cSQLDA = 4342438496, ivar_ptr = 0xffffffff7d7f3250, len_ptr = 0xffffffff7d7f3248, prec_ptr = 0xffffffff7d7f3240, scale_ptr = 0xffffffff7d7f3238, htype_ptr = 0xffffffff7d7f3230, param_type_ptr = 0xffffffff7d7f3228), line 900 in "SQLDA.cxx"
      [13] 0xffffffff7600d558(0x1018431d0, 0xffffffff7d7f3268, 0xffffffff7d7f3140, 0xfffffffffffffef0, 0xffffffff3546a010, 0x0), at 0xffffffff7600d558
      [14] 0xffffffff7600d500(0xffffffff38e600b0, 0xffffffff7d7f3350, 0x0, 0x48, 0xffffffff3546a010, 0xffffffff7d7f2971), at 0xffffffff7600d500
      [15] 0xffffffff76005fdc(0xffffffff38e600b0, 0xb6, 0x0, 0xffffffff76018a00, 0xffffffff37d8fe80, 0xffffffff7d7f2aa1), at 0xffffffff76005fdc
      [16] 0xffffffff76005fdc(0xffffffff7d7f9f50, 0x7a400, 0x0, 0xffffffff76018a30, 0xffffffff37d76ea8, 0xffffffff7d7f2bc1), at 0xffffffff76005fdc
      [17] 0xffffffff7600024c(0xffffffff7d7f35e0, 0xffffffff7d7f3980, 0xa, 0xfffffffeb06d3488, 0xffffffff7600be40, 0xffffffff7d7f3848), at 0xffffffff7600024c
      [18] JavaCalls::call_helper(0x7, 0x101843000, 0xffffffff7d7f3808, 0xa, 0xffffffff760001e0, 0xffffffff7d7f35b0), at 0xffffffff7b9d6348
      [19] JavaCalls::call(0xffffffff7d7f3978, 0x101843b50, 0xffffffff7d7f3808, 0x101843000, 0xa33c00, 0xa294f4), at 0xffffffff7b9e0b3c
      [20] jni_invoke_nonstatic(0xfffffffeb06d3488, 0xffffffff7d7f3978, 0x101843b50, 0x101843730, 0x101843b18, 0xffffffff7d7f3948), at 0xffffffff7ba0bae0
      [21] jni_CallIntMethodV(0x1018431d0, 0x101844840, 0xffffffff7c478b80, 0xffffffff7d7f3b38, 0x101843000, 0xa), at 0xffffffff7be0f798
      [22] JNIEnv_::CallIntMethod(this = 0x1018431d0, obj = 0x101844840, methodID = 0x101905f28, ...), line 969 in "jni.h"
      [23] trigger_proc_t::execute(this = 0x1015f9910, ARG2 = (nil), ARG3 = (nil)), line 708 in "xec_trg.cxx"

        • 1. Re: Intermittent JVM crashes with JVM 1.6.0_27
          user1552907 wrote:
          And for that we use JNI interface.
          Bug in the JNI code.
          We did not observe any crashes when we changed the jvm to 1.5.0_11 from 1.6.0_27 version of JDK.
          Execution path changed - because the code did. So the bug you had before did cause the system to choke. Now it does.
          • 2. Re: Intermittent JVM crashes with JVM 1.6.0_27
            Thanks for the reply.

            We noticed that crash always happens at the time of allocating some object in jvm. Hence, we thought that JVM could be running out of memory and we tried with the larger heap size and perm size but still it crashes.

            One thing, which we noticed is when we use minimum heap size (-Xms) and maximum heap size (-Xmx) as 3gb, it does not crash. Note that, both min and max heap values need to be same and should be 3gb (for our system, which has 10 GB of RAM). Does it give any clue?

            We have been trying to get the hs_err_pid file, but for some it is not generated. Any idea? We checked that the user has permissions on directory where the process is running. Also, we tried passing -X:ErrFile option. We have also disabled the the signal handling which we do.

            Here is the snippet of the crashing threads from 2 pstack output. Can something go wrong in the jvm while allocating memory for the object?

            Crashing thread:
            ----------------- lwp# 35 / thread# 35 --------------------
            Crashed at ffffffff7b9abf58 __1cSInterpreterRuntimeInewarray6FpnKJavaThread_nJBasicType_i_v_ (101915000, ffffffff7c5d3930, 81928, 10191500, 81930, ffffffff7c552000) + 210
            ffffffff76019614 * java/util/Arrays.copyOfRange([CII)[C+40 (line 5385)
            ffffffff76006ca8 * java/lang/String.<init>([CII)V+65 (line 455)
            ffffffff76006ff0 * java/lang/StringBuilder.toString()Ljava/lang/String;+13 (line 810)
            ffffffff76006ca8 * com/progress/sql/sp/SQLDA.setParam(ILjava/lang/Object;)V+32 (line 344)
            ffffffff7600024c * StubRoutines (1)
            ffffffff7ba14a4c __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f21b0, 101915000, 3, e, 3, 3) + 2fc
            ffffffff7ba21754 __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f21b0, 101915a98, ffffffff7d7f2020, 101915000, b3d800, b308d8) + 3c
            ffffffff7ba4c168 __1cUjni_invoke_nonstatic6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_ (1019151d0, ffffffff7d7f21b0, fffffffed0699368, 101915e70, 1014c4570, ffffffff7d7f2180) + 5c8
            ffffffff7bed288c jni_CallVoidMethodV (1019151d0, ffffffff7d7f2d88, 101a42768, ffffffff7d7f2358, 101915000, 101a405f1) + 2c0
            00000001005f154c __1cHJNIEnv_OCallVoidMethod6MpnI_jobject_pnK_jmethodID_E_v_ (1019151d0, ffffffff7d7f2d88, 101a42768, 15, 102a559a0, 101915000) + 4c
            00000001005ffe7c Java_com_progress_sql_sp_SQLDA_fromC (1019151d0, ffffffff7d7f2d88, 1016ae170, ffffffff7d7f2d70, ffffffff7d7f2d68, ffffffff7d7f2d60) + 203c
            ffffffff7600fd94 * com/progress/sql/sp/SQLDA.fromC(J[I[I[I[S[I[S)V+-25505
            ffffffff7600fd3c * com/progress/sql/sp/SQLDA.fromC(J[I[I[I[S[I[S)V+0
            ffffffff76006ff0 * com/progress/sql/sp/SQLDA.fromC_wrapper(J)V+26 (line 1402)
            ffffffff76006ff0 * com/progress/sql/sp/JavaBaseSP.dhTPdriver(JIJI)I+130 (line 329)
            ffffffff7600024c * StubRoutines (1)
            ffffffff7ba14a4c __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f34d0, 101915000, 7, a, 7, 7) + 2fc
            ffffffff7ba21754 __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f34d0, 101915a88, ffffffff7d7f3340, 101915000, b3d800, b308d8) + 3c
            ffffffff7ba4c168 __1cUjni_invoke_nonstatic6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_ (1019151d0, ffffffff7d7f34d0, fffffffed06a1788, 101915e70, 1014c4570, ffffffff7d7f34a0) + 5c8
            ffffffff7becf2e4 jni_CallIntMethodV (1019151d0, 102a57ba0, 101a42758, ffffffff7d7f3688, 101915000, 1028f9ca1) + 2c0
            0000000100603e2c __1cHJNIEnv_NCallIntMethod6MpnI_jobject_pnK_jmethodID_E_i_ (1019151d0, 102a57ba0, 101a42758, 0, 0, 1016ae170) + 4c

            Second pstack snippet (crashing thread):

            Crashed at  ffffffff7b1ab008 JVM_CurrentThread (1019a79d0, 1019a7800, 1ffc, ffffffff7af00000, 1019a780, ffffffff7bc0a000) + b0
            ffffffff7600d558 * java/lang/Thread.currentThread()Ljava/lang/Thread;+29689
            ffffffff7600d500 * java/lang/Thread.currentThread()Ljava/lang/Thread;+0
            ffffffff76005e60 * java/lang/ThreadLocal.get()Ljava/lang/Object;+0
            ffffffff76005e60 * java/util/TimeZone.getDefaultRef()Ljava/util/TimeZone;+3 (line 1042)
            ffffffff76005e60 * java/util/Date.normalize()Lsun/util/calendar/BaseCalendar$Date;+60 (line 2363)
            ffffffff76005e60 * java/util/Date.getTimeImpl()J+18 (line 1741)
            ffffffff76005ef8 * java/util/Date.<init>(IIIIII)V+103 (line 461)
            ffffffff76005fdc * java/util/Date.<init>(III)V+7 (line 356)
            ffffffff76005fdc * java/sql/Date.<init>(III)V+4 (line 74)
            ffffffff7600024c * StubRoutines (1)
            ffffffff7b1d6348 __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (4, 1019a7800, ffffffff7d7f2648, a, ffffffff760001e0, ffffffff7d7f23f0) + 1f8
            ffffffff7b1e0b3c __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f27b8, 1019a8360, ffffffff7d7f2648, 1019a7800, a33c00, a294f4) + 34
            ffffffff7b20bae0 __1cUjni_invoke_nonstatic6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_ (fffffffed06daa90, ffffffff7d7f27b8, 1019a8360, 1019a8710, 1019a8af8, ffffffff7d7f2788) + 528
            ffffffff7b289994 jni_NewObjectV (1019a79d0, ffffffff7d7f2788, ffffffff7bc78b80, ffffffff7d7f2978, 1019a7800, fffffffed06daa38) + 3e4
            00000001005f50b4 __1cHJNIEnv_JNewObject6MpnH_jclass_pnK_jmethodID_E_pnI_jobject__ (1019a79d0, 102874060, 101a69b18, 71, 4, 11) + 4c
            00000001006022e0 Java_com_progress_sql_sp_SQLDA_fromC (1019a79d0, ffffffff7d7f33a8, 101921bf0, ffffffff7d7f3390, ffffffff7d7f3388, ffffffff7d7f3380) + df8
            ffffffff7600d558 * com/progress/sql/sp/SQLDA.fromC(J[I[I[I[S[I[S)V+255
            ffffffff7600d500 * com/progress/sql/sp/SQLDA.fromC(J[I[I[I[S[I[S)V+0
            ffffffff76005fdc * com/progress/sql/sp/SQLDA.fromC_wrapper(J)V+26 (line 1402)
            ffffffff76005fdc * com/progress/sql/sp/JavaBaseSP.dhTPdriver(JIJI)I+130 (line 329)
            ffffffff7600024c * StubRoutines (1)
            ffffffff7b1d6348 __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (7, 1019a7800, ffffffff7d7f3948, a, ffffffff760001e0, ffffffff7d7f36f0) + 1f8
            ffffffff7b1e0b3c __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f3ab8, 1019a8330, ffffffff7d7f3948, 1019a7800, a33c00, a294f4) + 34
            ffffffff7b20bae0 __1cUjni_invoke_nonstatic6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_ (fffffffed06d3480, ffffffff7d7f3ab8, 1019a8330, 1019a8710, 1019a8af8, ffffffff7d7f3a88) + 528
            ffffffff7b60f798 jni_CallIntMethodV (1019a79d0, 102887620, ffffffff7bc78b80, ffffffff7d7f3c78, 1019a7800, a) + 1b8
            00000001006074d4 __1cHJNIEnv_NCallIntMethod6MpnI_jobject_pnK_jmethodID_E_i_ (1019a79d0, 102887620, 101a69af8, 0, 0, 101921bf0) + 4c
            000000010061fb58 __1cOtrigger_proc_tHexecute6MpkcpnKfldl_val_t__l_ (101842ef0, 1011ef579, ffffffff7d7f5028, ffffffff7d7f5c0e, 0, ffffffff7d7f4f5f) + 15b8

            Thanks in Advance,
            • 3. Re: Intermittent JVM crashes with JVM 1.6.0_27
              user1552907 wrote:
              Thanks for the reply.

              We noticed that crash always happens at the time of allocating some object in jvm.
              False cause.

              A memory bug in C/C++ corrupts the process space of the executable. "Crashes" occur when an application does something wrong ans the OS sees that.

              The second however can occur LONG after the actual code that is responsible for the first.

              For EXAMPLE if something corrupted the C++ heap then at some point an attempt to do an allocation will cause the application to fail.

              Although it is possible that the exact point where the exception occurs has the bad code that is actually rather unlikely because errors like that will occur immediately and all the time. Sporadic ones or ones that only show up after other code changes (new VM release) are more likely to be in other code.
              • 4. Re: Intermittent JVM crashes with JVM 1.6.0_27
                Thanks for the reply.

                I understand that, it can be a false cause (i.e, JVM always failing while allocating some object). Do you have any idea why we do not get crashes when we set both minimum and maximum heap size to some big number (3GB, in our case).

                Also, today we noticed a new crash pattern. The only difference in the our code is we have invoked System.gc before each run. We have browsed complete JNI code but did not find any issue with it. Any help would be appreciated.

                pstack number one:

                From dbx
                t@11 (l@11) signal SEGV (no mapping at the fault address) in CardTableExtension::scavenge_contents at 0xffffffff7baa4f6c
                0xffffffff7baa4f6c: scavenge_contents+0x0404: ldx [%o3 + 184], %o2
                current thread: t@11
                =>[1] CardTableExtension::scavenge_contents(0x10191be40, 0x10191c960, 0xfffffffed04a8110, 0xffffffffffffffff, 0xffffffff75800541, 0xffffffff7c552000), at
                [2] SerialOldToYoungRootsTask::do_it(0x102147040, 0x0, 0x10191c940, 0xffffffff7c552000, 0xaac4e8, 0xffffffff7c5d7e20), at 0xffffffff7baa5b68
                [3] GCTaskThread::run(0x10192f800, 0xffffffff7f005200, 0x10191f6a0, 0x101930080, 0x101930090, 0x101962960), at 0xffffffff7bb12d30
                [4] java_start(0x10192f800, 0x698f1, 0x82c00, 0x101931050, 0xffffffff7c552000, 0xffffffff7c5f44fc), at 0xffffffff7c177cb8

                pstack number 2:

                ----------------- lwp# 521 / thread# 521 --------------------
                ffffffff7c1482c8 __1cHMonitorEwait6Mblb_b_ (101915d40, 101917000, 0, 81930, ffffffff7b700000, 1700) + 170
                ffffffff7baa4508 __1cIVMThreadHexecute6FpnMVM_Operation__v_ (ffffffff7d7f2938, a0400, 101917000, 1, 282f74, ffffffff7c552000) + 1c0
                ffffffff7bae12cc __1cUParallelScavengeHeapHcollect6MnHGCCauseFCause__v_ (ffffffff7c5d1b30, 0, ffffffff7d7f2938, 7f800, ffffffff7c552000, 7fb30) + 74
                ffffffff7bae2c20 JVM_GC (ffffffff7c5d3940, 101917000, 0, 0, ffffffff7c552000, 81800) + 168
                ffffffff7a61468c Java_java_lang_Runtime_gc (1019171d0, ffffffff7d7f2d88, ffffffff7d7f2d80, ffffffff7d7f2d70, ffffffff7d7f2d68, ffffffff7d7f2d60) + 4
                ffffffff7600fd94 * java/lang/Runtime.gc()V+0
                ffffffff7600fd3c * java/lang/Runtime.gc()V+0
                ffffffff76006ff0 * java/lang/System.gc()V+3 (line 1964)
                ffffffff76006ff0 * com/progress/sql/sp/JavaBaseSP.dhTPdriver(JIJI)I+190 (line 346)
                ffffffff7600024c * StubRoutines (1)
                ffffffff7ba14a4c __1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f34d0, 101917000, 7, a, 7, 7) +
                ffffffff7ba21754 __1cJJavaCallsEcall6FpnJJavaValue_nMmethodHandle_pnRJavaCallArguments_pnGThread__v_ (ffffffff7d7f34d0, 101917748, ffffffff7d7f3340, 101
                917000, b3d800, b308d8) + 3c
                ffffffff7ba4c168 __1cUjni_invoke_nonstatic6FpnHJNIEnv__pnJJavaValue_pnI_jobject_nLJNICallType_pnK_jmethodID_pnSJNI_ArgumentPusher_pnGThread__v_ (1019171
                d0, ffffffff7d7f34d0, fffffffed06a1130, 101917b30, 1014c5db0, ffffffff7d7f34a0) + 5c8

                • 5. Re: Intermittent JVM crashes with JVM 1.6.0_27
                  Hi All,

                  Finally, it turned out to be an issue with JVM. When we disabled UseBiasedLocking (-XX:-UseBiasedLocking), then the crashes disappeared.

                  Just adding keyword, so that it helps in searching.

                  interpreterruntime::newarray jvm crash

                  JVM crashes while allocating memory


                  Edited by: user1552907 on May 24, 2013 2:35 AM
                  • 6. Re: Intermittent JVM crashes with JVM 1.6.0_27



                    Even after disabling JVM option, "-UseBiasedLocking", we could see the crash, but the crash frequency reduced to a large extent. Now, we see that the crash occurs after the script ran for over 48 hours. Earlier, we could reproduce the crash in few minutes. Can we get any clue out of it?


                    Based on the above results, can there be possibility of issue lying in JVM (when it uses this option)?




                    • 7. Re: Intermittent JVM crashes with JVM 1.6.0_27

                      Or, as I said, because the JNI is doing something wrong and the changing execution paths alter when the OS detects the problem.