On Tue, 12 Jul 2022 14:28:18 GMT, Zhengyu Gu <z...@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
