want your help
Yongqiang Yang
xiaoqiangnk at gmail.com
Thu Dec 9 23:01:27 PST 2010
On Fri, Dec 10, 2010 at 2:35 PM, David Holmes <David.Holmes at oracle.com> wrote:
>> 19 C 0x423ce6d8
>> 20 C 0x423ce6e0
>
> Are you able to decode these addresses to determine which VM functions they
> are?
The assert failure path I found is
Java_java_lang_ref_Finalizer_invokeFinalizeMethod
->jni_GetObjectClass
->jni_GetMethodID
->jni_CallVoidMethod
->jni_invoke_nonstatic
->Handle::Handle
->HandleArea::allocate_handle //here
assert failure.
As I said before, obj passed to jni_CallVoidMethod is invalid.
However, passed to GetObjectClass is valid. Between returning from
GetObjectClass and calling to CallVoidMethod obj'value is changed to
be invalid.
Thanks,
Yongqiang.
>
> 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
>>>>>>>>>>
>>>>>>
>>>>
>>>>
>>
>>
>>
>
--
Best Wishes
Yongqiang Yang
More information about the hotspot-dev
mailing list