JDK-4852569 : OBJ_ALLOC event deadlock between VMThread and Finalizer thread
  • Type: Bug
  • Component: vm-legacy
  • Sub-Component: jvmpi
  • Affected Version: 1.4.2
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2003-04-23
  • Updated: 2003-07-18
  • Resolved: 2003-06-05
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
1.4.2_02 02Fixed
Related Reports
Relates :  
Relates :  
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
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
16-07-2004

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.
16-07-2004

PUBLIC COMMENTS .
16-07-2004