JDK-8256830 : misc tests failed with "assert(env->is_enabled(JVMTI_EVENT_OBJECT_FREE)) failed: checking"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jvmti
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2020-11-21
  • Updated: 2020-12-07
  • Resolved: 2020-12-01
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.
JDK 16
16 b27Fixed
Related Reports
Relates :  
JDK-8212879 - Make JVMTI TagMap table concurrent
Description
The following test failed in the JDK16 CI:

vm/jvmti/ObjectFree/ofre001/ofre00101/ofre00101.html

Here's a snippet from the log file:

#section:testExecute
----------messages:(1/1276)*----------
command: com.sun.jck.lib.ExecJCKTestOtherJVMCmd PATH=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jck\\16\\b10\\extra\\bundles\\JCK-extra-16.zip\\JCK-extra-16\\binaries\\windows-amd64\\lib\\64bit SystemRoot=C:\\Windows SystemDrive=C: TMP=T:\\testoutput\\test-support\\jck_runtime_vm TEMP=T:\\testoutput\\test-support\\jck_runtime_vm C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-16+26-1682\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\java.exe -XX:+CreateCoredumpOnCrash -XX:+UseParallelGC -XX:+UseNUMA -XX:MaxRAMPercentage=3.125 --add-modules java.xml.crypto --add-exports java.xml.crypto/org.jcp.xml.dsig.internal.dom=ALL-UNNAMED -Xms32m -Xmx1024m -Djdk.attach.allowAttachSelf=true --enable-preview -agentlib:jckjvmti=ofre00101 -classpath C:\\ade\\mesos\\work_dir\\jib-master\\install\\jck\\16\\b10\\bundles\\JCK-runtime-16.jar\\JCK-runtime-16\\classes;;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jck\\16\\b10\\bundles\\JCK-runtime-16.jar\\JCK-runtime-16\\lib\\extensions\\JCK-extensions.jar -Djava.security.policy=C:\\ade\\mesos\\work_dir\\jib-master\\install\\jck\\16\\b10\\bundles\\JCK-runtime-16.jar\\JCK-runtime-16\\lib\\jck.policy javasoft.sqe.tests.vm.jvmti.ofre001.ofre00101.ofre00101 -platform.jvmtiSupported true -platform.nativeLibsLinkage dynamic
----------out1:(0/0)----------
----------out2:(18/1033)*----------
# To suppress the following error report, specify this argument
# after -XX: or in .hotspotrc:  SuppressErrorAt=t:/workspace/open/src/hotspot/share/prims/jvmtiExport.cpp:1490
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (t:/workspace/open/src/hotspot/share/prims/jvmtiExport.cpp:1490), pid=607740, tid=450616
#  assert(env->is_enabled(JVMTI_EVENT_OBJECT_FREE)) failed: checking
#
# JRE version: Java(TM) SE Runtime Environment (16.0+26) (fastdebug build 16-ea+26-1682)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 16-ea+26-1682, mixed mode, sharing, tiered, compressed oops, parallel gc, windows-amd64)
# Core dump will be written. Default location: T:\\testoutput\\test-support\\jck_runtime_vm\\hs_err_pid607740.mdmp
#
# An error report file with more information is saved as:
# T:\\testoutput\\test-support\\jck_runtime_vm\\hs_err_pid607740.log
#
# If you would like to submit a bug report, please visit:
#   https://bugreport.java.com/bugreport/crash.jsp
#
result: Failed. unexpected exit code: exit code 1
Comments
Changeset: 3a11009d Author: Coleen Phillimore <coleenp@openjdk.org> Date: 2020-12-01 13:07:41 +0000 URL: https://git.openjdk.java.net/jdk/commit/3a11009d
01-12-2020
So at #2 _needs_cleaning is reset to true but the event is disabled already. I've parsed your above comment now. ObjectFree event can be enabled and disabled concurrently to the service thread trying to post the event. Nothing protects the event disabling.
23-11-2020
Here's an interleaving that is not solved by gating on _needs_cleaning while holding the lock: thread1 is going to disable the event 1 thread1 cleans the table 2 something triggers GC 3 thread2 thread (perhaps ServiceThread) decides to clean and post 4 thread1 disables the event 5 thread2 posts even though event is disabled
23-11-2020
Even if two threads raced to remove_dead_entries, they should be gated by the _needs_cleaning flag while holding the lock: void JvmtiTagMap::remove_dead_entries_locked(bool post_object_free) { assert(is_locked(), "precondition"); if (_needs_cleaning) { log_info(jvmti, table)("TagMap table needs cleaning%s", (post_object_free ? " and posting" : "")); hashmap()->remove_dead_entries(env(), post_object_free); _needs_cleaning = false; } }
23-11-2020
Current thread (0x00007f0760307e10): VMThread "VM Thread" [stack: 0x00007f07456c6000,0x00007f07457c6000] [id=21647] Stack: [0x00007f07456c6000,0x00007f07457c6000], sp=0x00007f07457c48c0, free space=1018k Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.so+0x11e92fc] JvmtiExport::post_object_free(JvmtiEnv*, long)+0x8c V [libjvm.so+0x12293b2] JvmtiTagMapTable::remove_dead_entries(JvmtiEnv*, bool)+0x192 V [libjvm.so+0x12212cd] VM_JvmtiPostObjectFree::doit()+0x5d V [libjvm.so+0x198469a] VM_Operation::evaluate()+0x18a V [libjvm.so+0x19a7e7f] VMThread::evaluate_operation(VM_Operation*)+0x17f V [libjvm.so+0x19a88cc] VMThread::inner_execute(VM_Operation*)+0x17c V [libjvm.so+0x19a8b85] VMThread::loop()+0xb5 V [libjvm.so+0x19a8cba] VMThread::run()+0xca V [libjvm.so+0x1893db0] Thread::call_run()+0x100 V [libjvm.so+0x1574796] thread_native_entry(Thread*)+0x116 Looks like a call to JvmtiTagMap::post_dead_entries_on_vm_thread() while the event is disabled. I also just realized there's a race; any check for posting before calling that function could be followed by some other thread disabling the event, causing the vmthread posting to hit this assert. What's to stop that from happening even when the check is done by the VMOp? Nothing, since it runs concurrently rather than at a safepoint. Both calls to post_dead_entries_on_vm_thread are conditional on the event being enabled.
22-11-2020
Seems likely to be related to JDK-8212879 - [~coleenp]
22-11-2020
Good point! I've gotten used to filing JCK test failures as JCK bugs. I've moved this one to be a JDK bug.
22-11-2020
How is this a JCK issue when the VM is crashing?
22-11-2020