United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
JDK-4852569 : OBJ_ALLOC event deadlock between VMThread and Finalizer thread

Details
Type:
Bug
Submit Date:
2003-04-23
Status:
Resolved
Updated Date:
2003-07-18
Project Name:
JDK
Resolved Date:
2003-06-05
Component:
vm-legacy
OS:
generic
Sub-Component:
jvmpi
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
1.4.2
Fixed Versions:
1.4.2_02 (02)

Related Reports
Backport:
Relates:
Relates:

Sub Tasks

Description
###@###.### 2003-04-23

During testing of my batch of fixes for Forte, I ran into a classic
deadlock between the VMThread and the Finalizer thread.

The VMThread is executing a VM operation at a safepoint and is blocked
on the agent's data_access_lock. The data_access_lock is held by the
Finalizer thread (t@5) which is blocked on the safepoint.

How did we get in this situation? The JNI CreateJavaVM() thread (t@1)
is trying to post VM initialization events. It uses the VM operation
VM_JVMPIPostObjAlloc to do the job. However, just before it did this,
it initialized the java_lang_ref_Finalizer class. That started a race
between the Finalizer thread (t@5), the ReferenceHandler thread (t@6)
and the VMThread.

If either the Finalizer or ReferenceHandler threads managed to post an
OBJ_ALLOC event before blocking on the safepoint, then the VMThread
would deadlock.

Here is a snippet from the VMThread's call trace:

THREAD t@4

t@4(l@5) stopped in ___lwp_mutex_lock at 0xff29bee0
0xff29bee0: ___lwp_mutex_lock+0x0008:   ta      0x8
current thread: t@4
  [1] ___lwp_mutex_lock(0x140630, 0x140620, 0x0, 0x0, 0x4, 0xfd681e04), at 0xff2
9bee0
=>[2] os::Solaris::mutex_lock(mx = 0x140630), line 179 in "os_solaris.hpp"
  [3] os::Solaris::OSMutex::lock(this = 0x140620), line 491 in "os_solaris.hpp"
  [4] ObjectMonitor::raw_enter(this = 0x140600, __the_thread__ = 0xe7310, isRawM
onitor = 1), line 452 in "objectMonitor_solaris.cpp"
  [5] jvmpi::raw_monitor_enter(lock_id = 0x140600), line 3059 in "jvmpi.cpp"
  [6] hprof_obj_alloc_event(env_id = 0x3ea18, class_id = (nil), is_array = 10, s
ize = 2097152, obj_id = 0xf0c00000, arena_id = 1, requested = 0), line 238 in "h
prof_object.c"
  [7] hprof_notify_event(event = 0xfd681690), line 552 in "hprof.c"
  [8] jvmpi::post_event_vm_mode(event = 0xfd681690, calling_thread = 0x3e970), l
ine 284 in "jvmpi.cpp"
  [9] jvmpi::post_object_alloc_event(obj = 0xf0c00000, bytesize = 2097152U, aren
a_id = 1, flag = 0), line 914 in "jvmpi.cpp"
  [10] Universe::jvmpi_object_alloc(obj = 0xf0c00000, bytesize = 2097152U), line
 891 in "universe.cpp"
  [11] IssueJVMPIobjAllocEvent::do_object(this = 0xfd6819f0, obj = 0xf0c00000),
line 301 in "jvmpi.cpp"
  [12] ContiguousSpace::object_iterate_from(this = 0xbda30, mark = CLASS, blk =
0xfd6819f0), line 553 in "space.cpp"
  [13] ContiguousSpace::object_iterate(this = 0xbda30, blk = 0xfd6819f0), line 5
46 in "space.cpp"
  [14] DefNewGeneration::object_iterate(this = 0xbc098, blk = 0xfd6819f0), line
377 in "defNewGeneration.cpp"
  [15] GenCollectedHeap::object_iterate(this = 0xbbc88, cl = 0xfd6819f0), line 6
45 in "genCollectedHeap.cpp"
  [16] VM_JVMPIPostObjAlloc::doit(this = 0xffbee500), line 316 in "jvmpi.cpp"


Here is a snippet from the Finalizer thread's call trace:

THREAD t@5

t@5(l@6) stopped in ___lwp_mutex_lock at 0xff29bee0
0xff29bee0: ___lwp_mutex_lock+0x0008:   ta      0x8
current thread: t@5
  [1] ___lwp_mutex_lock(0x3d810, 0x3d808, 0xfe6e0018, 0x0, 0xff3e2660, 0xfe54180
a), at 0xff29bee0
=>[2] os::Solaris::mutex_lock(mx = 0x3d810), line 179 in "os_solaris.hpp"
  [3] os::Solaris::Event::lock(this = 0x3d808), line 283 in "os_solaris.hpp"
  [4] Mutex::wait_for_lock_implementation(this = 0x3d7a0), line 26 in "mutex_sol
aris.inline.hpp"
  [5] Mutex::lock_without_safepoint_check(this = 0x3d7a0), line 91 in "mutex.cpp
"
  [6] SafepointSynchronize::block(thread = 0xe90e0), line 358 in "safepoint.cpp"
  [7] JavaThread::check_safepoint_and_suspend_for_native_trans(thread = 0xe90e0)
, line 1695 in "thread.cpp"
  [8] ThreadStateTransition::transition_from_native(thread = 0xe90e0, to = _thre
ad_in_vm), line 113 in "interfaceSupport.hpp"
  [9] ThreadInVMfromUnknown::ThreadInVMfromUnknown(this = 0xfbb803d4), line 148
in "interfaceSupport.hpp"
  [10] jvmpi::get_call_trace(trace = 0xfbb8044c, depth = 10), line 2995 in "jvmp
i.cpp"
  [11] hprof_get_trace(env_id = 0xe9188, depth = 10), line 185 in "hprof_trace.c
"
  [12] hprof_obj_alloc_event(env_id = 0xe9188, class_id = (nil), is_array = 8, s
ize = 80, obj_id = 0xf4ccf630, arena_id = 5, requested = 0), line 247 in "hprof_
object.c"
  [13] hprof_notify_event(event = 0xfbb80708), line 552 in "hprof.c"
  [14] jvmpi::post_event(event = 0xfbb80708), line 225 in "jvmpi.cpp"
  [15] jvmpi::post_event_vm_mode(event = 0xfbb80708, calling_thread = (nil)), li
ne 238 in "jvmpi.cpp"
  [16] jvmpi::post_object_alloc_event(obj = 0xf4ccf630, bytesize = 80U, arena_id
 = 5, flag = 0), line 914 in "jvmpi.cpp"
  [17] Universe::jvmpi_object_alloc(obj = 0xf4ccf630, bytesize = 80U), line 891
in "universe.cpp"

The complete thread dump is attached as threads.log.1.

###@###.### 2003-04-24

I have observed failures due to the bug in the following tests:

    nsk/hprof/options/_empty_/empty001
    nsk/hprof/options/cpu/cpu006
    nsk/hprof/options/cpu/cpu007
    nsk/hprof/options/cutoff/cutoff002
    nsk/hprof/options/depth/depth001
    nsk/hprof/options/depth/depth002
    nsk/hprof/options/doe/doe001
    nsk/hprof/options/format/format001
    nsk/hprof/options/format/format002
    nsk/hprof/options/format/format003
    nsk/hprof/options/format/format004
    nsk/hprof/options/heap/heap002
    nsk/hprof/options/lineno/lineno003
    nsk/hprof/options/lineno/lineno008
    nsk/hprof/options/monitor/monitor002
    nsk/hprof/options/monitor/monitor003
    nsk/hprof/options/monitor/monitor004
    nsk/hprof/options/net/net001
    nsk/hprof/options/net/net003

Not every test fails on every platform.

###@###.### 2003-07-15

The following tests failed in my Mantis-B28 (FCS) baseline testing:

    nsk/hprof/options/cpu/cpu005
    nsk/hprof/options/cutoff/cutoff003
    nsk/hprof/options/lineno/lineno001
    nsk/hprof/options/lineno/lineno002

The above test config was Solaris 8 SPARC java_g -Xmixed. For test
config Solaris 8 SPARC java_g -Xcomp, the following tests failed:

    nsk/hprof/options/cutoff/cutoff001
    nsk/hprof/options/heap/heap003

For test config Solaris 8 SPARC java_g -Xint, the following tests failed:

    nsk/hprof/options/doe/doe002
    nsk/hprof/options/thread/thread002


###@###.### 2003-07-29 (update 07-30)

For test config Solaris 8 SPARC java_g -server -Xmixed, the following
tests failed:

    nsk/hprof/options/cpu/cpu004
    nsk/hprof/options/depth/depth003

For test config Solaris 8 SPARC java_g -server -Xint, the following
tests failed:

    nsk/hprof/options/heap/heap001

                                    

Comments
PUBLIC COMMENTS

.
                                     
2004-07-16
EVALUATION

###@###.### 2003-04-23

jvmpi::post_vm_initialization_events() is called by the JNI CreateJavaVM()
thread to issue CLASS_LOAD and OBJ_ALLOC events for all pre-loaded classes.
It also issues THREAD_START events for all non-hidden JavaThreads that
happen to be on the threads list at that point. The JVM_INIT_DONE event is
posted after the call to jvmpi::post_vm_initialization_events().

The OBJ_ALLOC events are issued via the VM_JVMPIPostObjAlloc VM operation
and the JNI CreateJavaVM() thread waits for the VMThread to do that work.
The CLASS_LOAD and THREAD_START events are posted by JNI CreateJavaVM()
thread.

During VM startup, before jvmpi::post_vm_initialization_events() is called,
the java/lang/ref/Finalizer class is initialized (along with other key
classes). The static class initializer for the Finalizer class creates
and starts the Finalizer thread. The code is in:
src/share/classes/java/lang/ref/Finalizer.java.

The Finalizer class extends FinalReference which extends Reference. So
when the Finalizer class is initialized, the Reference class is also
initialized. The static class initializer for the Reference class creates
and starts the ReferenceHandler thread. The code is in:
src/share/classes/java/lang/ref/Reference.java.

The JNI CreateJavaVM() thread inadvertently starts a three-way race when
OBJ_ALLOC events are enabled. The VMThread is trying post the OBJ_ALLOC
events for the pre-loaded classes. The Finalizer and ReferenceHandler
threads are trying to post their OBJ_ALLOC events.

When the timing is just right, either the Finalizer or ReferenceHandler
thread is posting an OBJ_ALLOC event and the OBJ_ALLOC event handler
grabs a lock and is about to make a call back into the VM to get some
other piece of information. Meanwhile the VMThread has started a
safepoint just after the initial OBJ_ALLOC event is posted. When the
OBJ_EVENT handler calls back into the VM, it blocks on the safepoint
(while holding the lock). The VMThread sees all threads as "synchronized"
and executes the VM_JVMPIPostObjAlloc VM operation. When the VMThread
posts the OBJ_ALLOC event, the OBJ_ALLOC event handler blocks on the
lock. We have deadlock!


###@###.### 2003-04-25

The situation can be slightly more complicated that what I described
before:

1) Any event handler can make a request for an OBJ_ALLOC event. If that
   request is blocked because of the in process VM_JVMPIPostObjAlloc
   VM operation, then any resources the original event handler is holding
   at the time may also cause a deadlock.
2) Any event handler may use the same resources as the agent's OBJ_ALLOC
   event handler. So a non-OBJ_ALLOC event handler may still cause the
   VMThread's OBJ_ALLOC event posting to deadlock.

Looks like we can't allow any JavaThread event posting to happen while
the VMThread is doing the housekeeping. Fortunately, this only happens
once and very early in VM startup.


###@###.### 2003-04-28

Another situation has popped up on uniprocessor machines. The JNI
CreateJavaVM() thread can try to post events before requesting the
VM_JVMPIPostObjAlloc VM operation. On a uniprocessor machine these
are usually MONITOR_CONTENDED_ENTERED events. However, the thread
will be blocked by the logic that disallows posting of events by
JavaThreads early in VM startup.

The post event blocking logic will need to allow the VMThread and
the JNI CreateJavaVM() thread to both post events.
                                     
2004-07-16
CONVERTED DATA

BugTraq+ Release Management Values

COMMIT TO FIX:
1.4.2_02
tiger

FIXED IN:
1.4.2_02
tiger

INTEGRATED IN:
1.4.2_02
tiger
tiger-b08


                                     
2004-07-16



Hardware and Software, Engineered to Work Together