JDK-8233454 : Test fails with assert(!is_init_completed(), "should only happen during init") after JDK-8229516
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 14
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2019-11-04
  • Updated: 2019-11-14
  • Resolved: 2019-11-07
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 14
14 b23Fixed
Related Reports
Relates :  
JDK-8233549 - Thread interrupted state must only be accessed when not in a safepoint-safe state
Relates :  
JDK-8229516 - Thread.isInterrupted() always returns false after thread termination
Relates :  
JDK-8233520 - Shenandoah: do not sleep when thread is attaching
Description
* Reproduce
-----------------------------------------
make test TEST="gc/logging/TestGCId.java"  CONF=fastdebug
-----------------------------------------

* Symptom
-----------------------------------------
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (/home/fool/workspace/jdk-dev/src/hotspot/share/classfile/javaClasses.cpp:1687), pid=19448, tid=19451
#  assert(!is_init_completed()) failed: should only happen during init
#
# JRE version: OpenJDK Runtime Environment (14.0) (fastdebug build 14-internal+0-adhoc.fool.jdk-dev)
# Java VM: OpenJDK 64-Bit Server VM (fastdebug 14-internal+0-adhoc.fool.jdk-dev, mixed mode, sharing, tiered, compressed oops, shenandoah gc, linux-amd64)
# Problematic frame:
# V  [libjvm.so+0xe185d1]  java_lang_Thread::interrupted(oop)+0x231
-----------------------------------------

* gdb bt
-----------------------------------------
#0  0x00007ffff5a37a80 in java_lang_Thread::interrupted (java_thread=0x0) at /home/fool/workspace/jdk-dev/src/hotspot/share/classfile/javaClasses.cpp:1687
#1  0x00007ffff61ba45d in JavaThread::is_interrupted (this=0x7ffff0074800, clear_interrupted=true) at /home/fool/workspace/jdk-dev/src/hotspot/share/runtime/thread.cpp:1744
#2  0x00007ffff61bf938 in JavaThread::sleep (this=0x7ffff0074800, millis=1) at /home/fool/workspace/jdk-dev/src/hotspot/share/runtime/thread.cpp:3407
#3  0x00007ffff609a3bb in ShenandoahPacer::pace_for_alloc (this=0x7ffff00ac250, words=22607) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shenandoah/shenandoahPacer.cpp:258
#4  0x00007ffff60732cd in ShenandoahHeap::allocate_memory (this=0x7ffff0086cc0, req=...) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp:802
#5  0x00007ffff60730c4 in ShenandoahHeap::allocate_new_tlab (this=0x7ffff0086cc0, min_size=256, requested_size=22607, actual_size=0x7ffff7fddad8)
    at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp:759
#6  0x00007ffff5e20e52 in MemAllocator::allocate_inside_tlab_slow (this=0x7ffff7fddb20, allocation=...) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shared/memAllocator.cpp:318
#7  0x00007ffff5e20d23 in MemAllocator::allocate_inside_tlab (this=0x7ffff7fddb20, allocation=...) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shared/memAllocator.cpp:278
#8  0x00007ffff5e21003 in MemAllocator::mem_allocate (this=0x7ffff7fddb20, allocation=...) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shared/memAllocator.cpp:350
#9  0x00007ffff5e21068 in MemAllocator::allocate (this=0x7ffff7fddb20) at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shared/memAllocator.cpp:363
#10 0x00007ffff5a0bdd5 in CollectedHeap::obj_allocate (this=0x7ffff0086cc0, klass=0x800132e08, size=46, __the_thread__=0x7ffff0074800)
    at /home/fool/workspace/jdk-dev/src/hotspot/share/gc/shared/collectedHeap.inline.hpp:72
#11 0x00007ffff59fff53 in InstanceKlass::allocate_instance (this=0x800132e08, __the_thread__=0x7ffff0074800) at /home/fool/workspace/jdk-dev/src/hotspot/share/oops/instanceKlass.cpp:1277
#12 0x00007ffff59fffdd in InstanceKlass::allocate_instance_handle (this=0x800132e08, __the_thread__=0x7ffff0074800) at /home/fool/workspace/jdk-dev/src/hotspot/share/oops/instanceKlass.cpp:1285
#13 0x00007ffff61b8d28 in JavaThread::allocate_threadObj (this=0x7ffff0074800, thread_group=..., thread_name=0x7ffff65e71a0 "DestroyJavaVM", daemon=false, __the_thread__=0x7ffff0074800)
    at /home/fool/workspace/jdk-dev/src/hotspot/share/runtime/thread.cpp:1203
#14 0x00007ffff5aff937 in attach_current_thread (vm=0x7ffff7087710 <main_vm>, penv=0x7ffff7fddd98, _args=0x7ffff7fdddb0, daemon=false) at /home/fool/workspace/jdk-dev/src/hotspot/share/prims/jni.cpp:4080
#15 0x00007ffff5affb11 in jni_AttachCurrentThread (vm=0x7ffff7087710 <main_vm>, penv=0x7ffff7fddd98, _args=0x7ffff7fdddb0) at /home/fool/workspace/jdk-dev/src/hotspot/share/prims/jni.cpp:4134
#16 0x00007ffff5b003ac in JavaVM_::AttachCurrentThread (this=0x7ffff7087710 <main_vm>, penv=0x7ffff7fddd98, args=0x7ffff7fdddb0)
    at /home/fool/workspace/jdk-dev/build/linux-x86_64-server-slowdebug/support/modules_include/java.base/jni.h:1939
#17 0x00007ffff5aff64e in jni_DestroyJavaVM_inner (vm=0x7ffff7087710 <main_vm>) at /home/fool/workspace/jdk-dev/src/hotspot/share/prims/jni.cpp:3982
#18 0x00007ffff5aff6db in jni_DestroyJavaVM (vm=0x7ffff7087710 <main_vm>) at /home/fool/workspace/jdk-dev/src/hotspot/share/prims/jni.cpp:4008
#19 0x00007ffff7bc5d9e in JavaMain (_args=0x7fffffffaaf0) at /home/fool/workspace/jdk-dev/src/java.base/share/native/libjli/java.c:557
#20 0x00007ffff7bccccd in ThreadJavaMain (args=0x7fffffffaaf0) at /home/fool/workspace/jdk-dev/src/java.base/unix/native/libjli/java_md_solinux.c:740
#21 0x00007ffff71976db in start_thread (arg=0x7ffff7fde700) at pthread_create.c:463
#22 0x00007ffff78f188f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
-----------------------------------------
Comments
URL: https://hg.openjdk.java.net/jdk/jdk/rev/9a0a5e70eeb2 User: dholmes Date: 2019-11-07 02:19:56 +0000
07-11-2019
ILW = HLL = P4
05-11-2019
[~dholmes] I agree with you that the runtime shared code should also be fixed. Just feel free to take this issue. Thanks.
05-11-2019
Proposed fix: http://cr.openjdk.java.net/~dholmes/8233454/webrev/
04-11-2019
[~shade] I think having an attaching thread perform a sleep is somewhat dubious, so the proposed shenandoah change looks good. But I'm also thinking the interruption code needs to be more resilient in this situation, so I'm going to change the general logic here, as well as the assert itself. [~jiefu] I hope you don't mind but I'll take this issue from you. BTW I couldn't get either of the reproducers to fail for me locally :(
04-11-2019
Existing reproducer: $ CONF=linux-x86_64-server-fastdebug make images run-test TEST=gc/logging/TestGCId.java This might be better fixed on Shenandoah side: http://cr.openjdk.java.net/~shade/8233454/webrev.01/ Forked it to JDK-8233520, and would fix Shenandoah there. If David thinks assert in the shared code needs to be changed, please keep using this issue.
04-11-2019
I need to take a closer look at this. Shenandoah really shouldn't be having a thread do a sleep() whilst it is still in the process of attaching to the JVM. The correct fix may be to check is_attaching rather than has_attached.
04-11-2019
RFR: https://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2019-November/036758.html
04-11-2019
It might be fixed by ``` diff -r 2700c409ff10 src/hotspot/share/classfile/javaClasses.cpp --- a/src/hotspot/share/classfile/javaClasses.cpp Sun Nov 03 18:02:29 2019 -0500 +++ b/src/hotspot/share/classfile/javaClasses.cpp Mon Nov 04 16:49:39 2019 +0800 @@ -1684,7 +1684,8 @@ #if INCLUDE_JFR if (java_thread == NULL) { // can happen from Jfr::on_vm_init leading to call of JavaThread::sleep - assert(!is_init_completed(), "should only happen during init"); + assert(!is_init_completed() || JavaThread::current()->has_attached_via_jni(), + "should only happen during init or for threads attached via JNI"); return false; } #endif ```
04-11-2019
Reproducer: ```java public class GCTest { private static byte[] garbage; public static void main(String [] args) { System.out.println("Creating garbage"); // create 128MB of garbage. This should result in at least one GC for (int i = 0; i < 1024; i++) { garbage = new byte[128 * 1024]; } // do a system gc to get one more gc System.gc(); System.out.println("Done"); } } ``` ``` ${JDK}/bin/javac GCTest.java ${JDK}/bin/java -XX:+UnlockExperimentalVMOptions -XX:+UseShenandoahGC -Xlog:gc -Xmx10M GCTest ```
04-11-2019