On Tue, 12 Jul 2022 06:31:39 GMT, Chris Plummer <cjplum...@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.
-------------
PR: https://git.openjdk.org/jdk/pull/9168
