want your help

David Holmes David.Holmes at oracle.com
Thu Dec 9 22:35:19 PST 2010


 >  19 C  0x423ce6d8
 >  20 C  0x423ce6e0

Are you able to decode these addresses to determine which VM functions 
they are?

David

Yongqiang Yang said the following on 12/10/10 16:22:
> Hi David,
> 
> Here is stacktrace for the assertion failure.  The 1st column of
> number is line numbers.  Lines from 1 to 12 are comments beginning as
> a '#'.
> 
> Thanks,
> Yongqiang.
> 
>   1 #
>   2 # A fatal error has been detected by the Java Runtime Environment:
>   3 #
>   4 #  Internal Error
> (/home/yangyongqiang/hotspot6/hotspot/src/share/vm/runtime/handles.cpp:34),
> pid=17186, tid=11    11291088
>   5 #  assert(SharedSkipVerify || obj->is_oop()) failed: sanity check
>   6 #
>   7 # JRE version: 6.0
>   8 # Java VM: OpenJDK Client VM (19.0-b09-internal-jvmg compiled mode
> linux-mips )
>   9 # If you would like to submit a bug report, please visit:
>  10 #   http://java.sun.com/webapps/bugreport/crash.jsp
>  11 #
>  12
>  13 ---------------  T H R E A D  ---------------
>  14
>  15 Current thread (0x00482400):  JavaThread "Finalizer" daemon
> [_thread_in_vm, id=17190, stack(0x42380000,0x423d00    00)]
>  16
>  17 Stack: [0x42380000,0x423d0000],  sp=0x423ce6c8,  free space=313k
>  18 Native frames: (J=compiled Java code, j=interpreted, Vv=VM code,
> C=native code)
>  19 C  0x423ce6d8
>  20 C  0x423ce6e0
>  21
>  22 Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
>  23 J  java.lang.ref.Finalizer.invokeFinalizeMethod(Ljava/lang/Object;)V
>  24 J  java.lang.ref.Finalizer.runFinalizer()V
>  25 J  java.lang.ref.Finalizer.access$100(Ljava/lang/ref/Finalizer;)V
>  26 j  java.lang.ref.Finalizer$FinalizerThread.run()V+11
>  27 v  ~StubRoutines::call_stub
>  28
>  29 ---------------  P R O C E S S  ---------------
>  30
>  31 Java Threads: ( => current thread )
>  32   0x004fb000 JavaThread "Low Memory Detector" daemon
> [_thread_blocked, id=17193, stack(0x424a0000,0x424f0000)]
>  33   0x00497000 JavaThread "CompilerThread0" daemon [_thread_blocked,
> id=17192, stack(0x42420000,0x424a0000)]
>  34   0x00495000 JavaThread "Signal Dispatcher" daemon
> [_thread_blocked, id=17191, stack(0x423d0000,0x42420000)]
>  35 =>0x00482400 JavaThread "Finalizer" daemon [_thread_in_vm,
> id=17190, stack(0x42380000,0x423d0000)]
>  36   0x0047d000 JavaThread "Reference Handler" daemon
> [_thread_blocked, id=17189, stack(0x42330000,0x42380000)]
>  37   0x00437c00 JavaThread "main" [_thread_blocked, id=17187,
> stack(0x2bd6c000,0x2bdbc000)]
>  38
>  39 Other Threads:
>  40   0x00478800 VMThread [stack: 0x422b0000,0x42330000] [id=17188]
>  41   0x00501800 WatcherThread [stack: 0x424f0000,0x42570000] [id=17194]
>  42
>  43 VM state:not at safepoint (normal execution)
>  44
>  45 VM Mutex/Monitor currently owned by a thread:  ([mutex/lock_event])
>  46 [0x004358a8] Heap_lock - owner thread: 0x00437c00
>  47
>  48 Heap
>  49  def new generation   total 4864K, used 87K [0x2dfa0000,
> 0x2e4e0000, 0x334f0000)
>  50   eden space 4352K,   1% used [0x2dfa0000, 0x2dfb5c28, 0x2e3e0000)
>  51   from space 512K,   0% used [0x2e3e0000, 0x2e3e0000, 0x2e460000)
>  52   to   space 512K,   0% used [0x2e460000, 0x2e460000, 0x2e4e0000)
>  53  tenured generation   total 10688K, used 101K [0x334f0000,
> 0x33f60000, 0x3dfa0000)
>  54    the space 10688K,   0% used [0x334f0000, 0x335097f0,
> 0x33509800, 0x33f60000)
>  55  compacting perm gen  total 12288K, used 1620K [0x3dfa0000,
> 0x3eba0000, 0x41fa0000)
>  56    the space 12288K,  13% used [0x3dfa0000, 0x3e135290,
> 0x3e135400, 0x3eba0000)
>  57 No shared spaces configured.
> 
> 
> On Fri, Dec 10, 2010 at 10:59 AM, David Holmes <David.Holmes at oracle.com> wrote:
>> Yongqiang Yang said the following on 12/10/10 12:42:
>>> On Fri, Dec 10, 2010 at 10:10 AM, David Holmes <David.Holmes at oracle.com>
>>> wrote:
>>>> I'm somewhat puzzled as to why the address is so often the same, but this
>>>> occurs with other platforms as well.
>>> I guess the reason is that System.gc() is invoked manually.  Before
>>> current allocation request comes, last allocated space has been
>>> recycled.
>> You are right, if I disable the System.gc() then the address changes.
>>
>> This reminded me that an object can be collected before its finalizer is
>> executed if the finalizer does not reference the 'this' reference in a way
>> that causes the the object to be retained (bit of a circular description I
>> know).
>>
>> That said I changed the finalizer to reference 'this' in a few ways and it
>> still seems that GC was able to reuse the same address. Strange.
>>
>> Hmmm I have an idea. Can you please show me the stacktrace for the assertion
>> failure from the hs_err log file.
> 
> 
> 
> 
>> David
>>
>>>> Beyond that I'm out of suggestions as to how and pin this down further -
>>>> sorry.
>>>>
>>>> David
>>>>
>>>> Yongqiang Yang said the following on 12/10/10 11:49:
>>>>> Hi ramki,
>>>>>
>>>>> Thank you for your help.
>>>>> I have done as you suggested and found nothing different.  I list my
>>>>> test program and output at end of this email.
>>>>>
>>>>> Apparentlym, object at 0x2dfa0000 was collected before finalized with
>>>>> Xcomp. However,  with Xint, everything is right.  Both Xcomp and Xint
>>>>> register finalizer through the same function
>>>>> instanceKlass::register_finalizer, where a handle for object is
>>>>> constructed.
>>>>>
>>>>> Yongqiang.
>>>>>
>>>>> My test program named finalexc.java is as follows.
>>>>>  public class finalexc {
>>>>>       static int f;
>>>>>       public void finalize() {
>>>>>            f++;
>>>>>            System.out.println("finalize " + f);
>>>>>   }
>>>>>   static void test() {
>>>>>        for (int i = 0; i < 100; i++) {
>>>>>             new finalexc();
>>>>>             System.gc();
>>>>>        }
>>>>>   }
>>>>>   public static void main(String av[]) {
>>>>>        while(true) test();
>>>>>   }
>>>>>  }
>>>>>
>>>>> java -Xcomp -XX:+TraceFinalizerRegistration finalexc
>>>>> Output is as follow.
>>>>> ===========================================================
>>>>> VM option '+TraceFinalizerRegistration'
>>>>> Registered a 'java/io/FileInputStream' (0x2dfa8910) as finalizable
>>>>> Registered a 'java/io/FileOutputStream' (0x2dfa89c8) as finalizable
>>>>> Registered a 'java/io/FileOutputStream' (0x2dfa8a08) as finalizable
>>>>> Registered a 'java/lang/ClassLoader$NativeLibrary' (0x2dfb4090) as
>>>>> finalizable
>>>>> Registered a 'java/io/FileInputStream' (0x2dfb4db8) as finalizable
>>>>> Registered a 'java/io/FileInputStream' (0x2dfc9e20) as finalizable
>>>>> Registered a 'finalexc' (0x2dfcbfb8) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> return 0x2b2a3618
>>>>> allocate_handle 33 0x5431f8
>>>>> # To suppress the following error report, specify this argument
>>>>> # after -XX: or in .hotspotrc:  SuppressErrorAt=/handles.cpp:34
>>>>> #
>>>>> # A fatal error has been detected by the Java Runtime Environment:
>>>>> #
>>>>> #  Internal Error
>>>>>
>>>>>
>>>>> (/home/yangyongqiang/hotspot6/hotspot/src/share/vm/runtime/handles.cpp:34),
>>>>> pid=17186, tid=1111291088
>>>>> #  assert(SharedSkipVerify || obj->is_oop()) failed: sanity check
>>>>> #
>>>>> # JRE version: 6.0
>>>>> # Java VM: OpenJDK Client VM (19.0-b09-internal-jvmg compiled mode
>>>>> linux-mips )
>>>>> # An error report file with more information is saved as:
>>>>> # /home/yangyongqiang/benchmark/regression/hs_err_pid17186.log
>>>>> @@@@@@@@@@@@@@@@@@@get_previous_fp = 0x423ce6c0
>>>>> @@@@@@@@@@@@@@@@@@@get_previous_fp = 0x423ce6c0
>>>>> #
>>>>> # If you would like to submit a bug report, please visit:
>>>>> #   http://java.sun.com/webapps/bugreport/crash.jsp
>>>>> #
>>>>> =========================================================
>>>>>
>>>>> With Xint, output is:
>>>>>
>>>>> =========================================================
>>>>> Registered a 'finalexc' (0x2dfcbe88) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfb5c60) as finalizable
>>>>> finalize 1
>>>>> finalize 2
>>>>> finalize 3
>>>>> finalize 4
>>>>> Registered a 'finalexc' (0x2dfb5c68) as finalizable
>>>>> finalize 5
>>>>> Registered a 'finalexc' (0x2dfb5c68) as finalizable
>>>>> finalize 6
>>>>> Registered a 'finalexc' (0x2dfb5c68) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> Registered a 'finalexc' (0x2dfa0000) as finalizable
>>>>> finalize 7
>>>>> finalize 8
>>>>> =======================================================
>>>>>
>>>>>
>>>>> On Fri, Dec 10, 2010 at 4:42 AM, Y. Srinivas Ramakrishna
>>>>> <y.s.ramakrishna at oracle.com> wrote:
>>>>>> Yongqiang, In addition to the suggestions already made,
>>>>>> you might also try -XX:+CheckUnhandleOops -XX:+VerifyBeforeGC
>>>>>> -XX:+VerifyAfterGC to
>>>>>> see if it sheds more light in the issue. (although these might
>>>>>> slow down execution and cause a race/bug to disappear.)
>>>>>>
>>>>>> best.
>>>>>> -- ramki
>>>>>>
>>>>>> On 12/9/2010 5:55 AM, Yongqiang Yang wrote:
>>>>>>> Hi David,
>>>>>>>
>>>>>>> Xint works well.  I think I did something wrong with finalizer, but I
>>>>>>> can't find it.
>>>>>>> When in Xcomp mode, finalize function is not called before object was
>>>>>>> collected.
>>>>>>> I am sure finalizer is registered.
>>>>>>>
>>>>>>> On Thu, Dec 9, 2010 at 3:06 PM, David Holmes<David.Holmes at oracle.com>
>>>>>>>  wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> Yongqiang Yang said the following on 12/09/10 16:44:
>>>>>>>>> Maybe I didn't elaborate the problem clearly.
>>>>>>>>>  Java_java_lang_ref_Finalizer_invokeFinalizeMethod is  a native
>>>>>>>>> method.
>>>>>>>>>  It
>>>>>>>>> invokes GetObjectClass and CallVoidMethod.   So jump to
>>>>>>>>> Java_java_lang_ref_Finalizer_invokeFinalizeMethod via a native
>>>>>>>>> wrapper.
>>>>>>>>>  Thus returns  from it uses a native return wrapper.   Callings or
>>>>>>>>> returns
>>>>>>>>> of GetObjectClass and CallVoidMethod are done by g++.
>>>>>>>> Sorry - You said you were porting to MIPS so I was pointing out that
>>>>>>>> the
>>>>>>>> problem might be in the MIPS code that handles native method calls eg
>>>>>>>> by
>>>>>>>> clobbering a register that might be used in the callee. But I just
>>>>>>>> realized
>>>>>>>> that is for calls from Java to native, not from native to Java - the
>>>>>>>> latter
>>>>>>>> is all basic C++ code as you point out.
>>>>>>>>
>>>>>>>>> The bug is as follows.
>>>>>>>>> Before return from GetObjectClass, the ob's value is right,  that it
>>>>>>>>> references a right object.  However, when CallVoidMethod begins,  ob
>>>>>>>>> references a invalid object.
>>>>>>>> Are you certain there is no gc occurring? If not, and the ob value
>>>>>>>> has
>>>>>>>> changed when GetObjectClass returns then I can only assume some kind
>>>>>>>> of
>>>>>>>> memory stomp during the execution of GetObjectClass. Can you add some
>>>>>>>> extra
>>>>>>>> local variables and check their values to see if it is a stack stomp?
>>>>>>>>
>>>>>>>> Does the problem occur with -Xint? Is compilation occurring
>>>>>>>> elsewhere?
>>>>>>>>
>>>>>>>> David
>>>>>>>> -----
>>>>>>>>
>>>>>>>>> During the change, Finalizer-Thread is in native method
>>>>>>>>> Java_java_lang_ref_Finalizer_invokeFinalizeMethod.  That says
>>>>>>>>> Finalizer-Thread runs codes compiled by g++ during the change.
>>>>>>>>>
>>>>>>>>> I think another thread changes ob's value, but I can't think of any
>>>>>>>>> thread
>>>>>>>>> except GC.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> On Thu, Dec 9, 2010 at 10:27 AM, David
>>>>>>>>> Holmes<David.Holmes at oracle.com
>>>>>>>>> <mailto:David.Holmes at oracle.com>>  wrote:
>>>>>>>>>
>>>>>>>>>  -Xcomp compiles every method on first use, rather than only
>>>>>>>>>  compiling when the method becomes "hot".
>>>>>>>>>
>>>>>>>>>  If the test passes in -Xmixed but not -Xcomp then it is likely that
>>>>>>>>>  in -Xmixed the problematic code is not getting compiled. (Use
>>>>>>>>>  -XX:+PrintCompilation to check - may need a debug VM for that).
>>>>>>>>>
>>>>>>>>>  The jobject is an opaque reference to the object for which
>>>>>>>>>  finalize() is to be invoked. Even if safepoints occur and GC occurs
>>>>>>>>>  etc, this should remain a valid reference. If that is not the case
>>>>>>>>>  then something is corrupting the value. The stacktrace from the
>>>>>>>>>  assert should show where the corruption is detected, which may
>>>>>>>>> help,
>>>>>>>>>  but it won't show where it occurred. It could be something as
>>>>>>>>> simple
>>>>>>>>>  as not setting up the correct register usage for return from the
>>>>>>>>>  native method - ie your method return from GetObjectClass might be
>>>>>>>>>  trashing the register that holds "ob". I think you would need to be
>>>>>>>>>  able to dump dissassenbly of both methods to see if there is
>>>>>>>>> obvious
>>>>>>>>>  corruption.
>>>>>>>>>
>>>>>>>>>  David Holmes
>>>>>>>>>
>>>>>>>>>  Yongqiang Yang said the following on 12/09/10 11:57:
>>>>>>>>>
>>>>>>>>>      Hi Gary,
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>      That you for your help very much.
>>>>>>>>>       I have looked as you suggested.  There is no safepoint rom
>>>>>>>>>      return at GetObjectClass to calling CallVoidMethod.
>>>>>>>>>      This bug  appears in Finalizer thread every time. Thus, I think
>>>>>>>>>      maybe there is a bug in finalizer.  When I use -Xcomp option,
>>>>>>>>>      finalize function is not called.  When I use mixed or
>>>>>>>>>      interpretered jvm, finalize is called.  I don't know what
>>>>>>>>>      happens in -Xcomp mode.  I  find that finalizer  is registered
>>>>>>>>>      using -XX:+TraceRegisterdFinalizer.
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>      On Wed, Dec 8, 2010 at 5:49 PM, Gary Benson<gbenson at redhat.com
>>>>>>>>>      <mailto:gbenson at redhat.com>  <mailto:gbenson at redhat.com
>>>>>>>>>      <mailto:gbenson at redhat.com>>>  wrote:
>>>>>>>>>
>>>>>>>>>         Hi Yongqiang,
>>>>>>>>>
>>>>>>>>>         Yongqiang Yang wrote:
>>>>>>>>>          >  Hi everyone,
>>>>>>>>>          >
>>>>>>>>>          >  I am porting hotspot to MIPS.  I meet a bug as follows.
>>>>>>>>>          >
>>>>>>>>>          >  In function
>>>>>>>>> Java_java_lang_ref_Finalizer_invokeFinalizeMethod,
>>>>>>>>>          >  value of jobject is right when call GetObjectClass and
>>>>>>>>>      also right
>>>>>>>>>          >  before return from GetObjectClass . However,  it is
>>>>>>>>> wrong
>>>>>>>>> when
>>>>>>>>>          >  calling CallVoidMethod.   For example, It is changed
>>>>>>>>> from
>>>>>>>>>      0x3e0885d0
>>>>>>>>>          >  to 0x423ce794.
>>>>>>>>>          >  Thus, it results in an assert failure below.
>>>>>>>>>          >
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>  ----------------------------------------------------------------------
>>>>>>>>>          >     assert(SharedSkipVerify || obj->is_oop()) failed:
>>>>>>>>> sanity
>>>>>>>>>      check
>>>>>>>>>          >
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>  ----------------------------------------------------------------------
>>>>>>>>>          >
>>>>>>>>>
>>>>>>>>>          >  I want to know who will change this value from return at
>>>>>>>>>         GetObjectClass
>>>>>>>>>          >  to calling CallVoidMethod.  During this time, GC don't
>>>>>>>>> run.
>>>>>>>>>
>>>>>>>>>          >
>>>>>>>>>          >  Could anyone have an idea about this?
>>>>>>>>>
>>>>>>>>>         Look at the source code to jni_GetMethodID and
>>>>>>>>>      jni_CallVoidMethod,
>>>>>>>>>         in hotspot/src/share/vm/prims/jni.cpp.  Notice the JNI_ENTRY
>>>>>>>>> and
>>>>>>>>>         JNI_END surrounding them?  Look at the source code for
>>>>>>>>> JNI_ENTRY,
>>>>>>>>>         in hotspot/src/share/vm/runtime/interfaceSupport.hpp.  Do
>>>>>>>>> you
>>>>>>>>> see
>>>>>>>>>         the ThreadInVMfromNative?  That object has a constructor and
>>>>>>>>> a
>>>>>>>>>         destructor, both of which contain thread state transitions.
>>>>>>>>>         Safepoints can occur during those transitions, and oops can
>>>>>>>>>      change
>>>>>>>>>         at any safepoint regardless of whether the GC runs.  You
>>>>>>>>>      could try
>>>>>>>>>         running with -XX:+TraceSafepoint or something like that to
>>>>>>>>> see
>>>>>>>>> if
>>>>>>>>>         one is occuring.
>>>>>>>>>
>>>>>>>>>         Cheers,
>>>>>>>>>         Gary
>>>>>>>>>
>>>>>>>>>         --
>>>>>>>>>         http://gbenson.net/
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>      --         Best Wishes
>>>>>>>>>      Yongqiang Yang
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> --
>>>>>>>>> Best Wishes
>>>>>>>>> Yongqiang Yang
>>>>>>>>>
>>>>>
>>>
>>>
> 
> 
> 


More information about the hotspot-dev mailing list