RFR: 8256811: Delayed/missed jdwp class unloading events [v15]

[Zhengyu Gu]

On Tue, 12 Jul 2022 14:28:18 GMT, Zhengyu Gu <zgu at openjdk.org> wrote:

> > It seems during test shutdown, ObjectFree events are being delivered after JVMTI events have been disabled:
> > ```
> >     nsk_jvmti_enableEvents(JVMTI_DISABLE, eventsCount, events, NULL);
> > 
> >     NSK_TRACE(jni->DeleteGlobalRef(debugeeClass));
> >     NSK_TRACE(jvmti->DestroyRawMonitor(counterMonitor_ptr));
> > 
> >     NSK_DISPLAY0("Let debugee to finish\n");
> > ```
> > 
> > 
> >     
> >       
> >     
> > 
> >       
> >     
> > 
> >     
> >   
> > The first line is disabling events. A couple statements later the monitor is freed. After that a printf that we are seeing in the output. After the printf the ObjectFree events arrives and we try to use the freed monitor. Here's the stack trace when the event arrives (I got this by inserting an assert(0)):
> > ```
> > #4  0x00007f451f6752af in increaseCounter (counterPtr=0x7f451f699ad8 <eventCount>) at /opt/mach5/mesos/work_dir/slaves/0c72054a-24ab-4dbb-944f-97f9341a1b96-S8484/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/fa6bd5a2-99f3-402f-b5bb-613077cc393c/runs/f384ea29-cdca-4da9-887c-7f0c9eff2c41/workspace/open/test/hotspot/jtreg/vmTestbase/nsk/share/native/JVMTITools.cpp:71
> > #5  0x00007f451dc10f13 in JvmtiExport::post_object_free(JvmtiEnv*, GrowableArray<long>*) () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #6  0x00007f451dc4772d in JvmtiTagMap::post_dead_objects(GrowableArray<long>*) () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #7  0x00007f451dc4804a in JvmtiTagMap::remove_and_post_dead_objects() () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #8  0x00007f451dc48615 in JvmtiTagMap::flush_all_object_free_events() () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #9  0x00007f451e15ed93 in ServiceThread::service_thread_entry(JavaThread*, JavaThread*) () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #10 0x00007f451d8ff948 in JavaThread::thread_main_inner() () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #11 0x00007f451e31ec20 in Thread::call_run() () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #12 0x00007f451dfe1ef4 in thread_native_entry(Thread*) () from /opt/mach5/mesos/work_dir/jib-master/install/2022-07-12-0516516.chris.plummer.zhengyu/linux-x64-debug.jdk/jdk-20/fastdebug/lib/server/libjvm.so
> > #13 0x00007f451f17d1df in start_thread () from /lib64/libpthread.so.0
> > #14 0x00007f451ebe5dd3 in clone () from /lib64/libc.so.6
> > ```
> > 
> > 
> >     
> >       
> >     
> > 
> >       
> >     
> > 
> >     
> >   
> > It's a little misleading because of some inlining. Here's the actual ObjectFree callback:
> > ```
> > void JNICALL
> > ObjectFree(jvmtiEnv *jvmti_env, jlong tag) {
> >     increaseCounter(&eventCount);
> > //    NSK_DISPLAY0("  event: ObjectFree\n");
> > }
> > ```
> > 
> > 
> >     
> >       
> >     
> > 
> >       
> >     
> > 
> >     
> >   
> > I'm a bit less sure now that this is a test bug. I wonder if some JVMTI synchronization is now being bypassed that would normally have blocked the test when it tried to disable events, and not allow the disabling until the ObjectFree events had all finished being posted.
> 
> I am perplexed where is the synchronization, I believe, there is none.
> 
> We were lucky to avoid this failure due to the test disables `JVMTI_EVENT_GARBAGE_COLLECTION_FINISH` along with `JVMTI_EVENT_OBJECT_FREE` at once. The old implementation was depending on `JVMTI_EVENT_GARBAGE_COLLECTION_FINISH` to flush `JVMTI_EVENT_OBJECT_FREE` events and `JVMTI_EVENT_GARBAGE_COLLECTION_FINISH` event is posted at safepoint, that gives illusion of synchronization.
> 
> I believe enabling/disabling events are always asynchronous vs posting them. Further more, setting event bits seems to require `JvmtiThreadState_lock` while reading does not.

Every time to enable/disable `JVMTI_EVENT_OBJECT_FREE` event, it does a flush. The problem is that it may race `ServiceThread` to flush dead objects. If `ServiceThread` tries to flush a `JvmtiTagMap` first and collect all dead objects, then blocked while another thread enables/disables `JVMTI_EVENT_OBJECT_FREE` event and completes a flush on the `JvmtiTagMap`, when `ServiceThread` unblocked and continues to flush, that causes the failure.

The solution is to serialize the flushes, so that above scenario can not happen.

-------------

PR: https://git.openjdk.org/jdk/pull/9168