JDK-8139937 : runtime/ParallelClassLoading/bootstrap/random/inner-complex hits G1 assert
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P2
  • Status: Resolved
  • Resolution: Cannot Reproduce
  • OS: linux
  • CPU: x86_64
  • Submitted: 2015-10-19
  • Updated: 2015-12-10
  • Resolved: 2015-12-10
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 9
9Resolved
Related Reports
Relates :  
Description
While chasing the following bug:

JDK-8047212 runtime/ParallelClassLoading/bootstrap/random/inner-complex assert(ObjectSynchronizer::verify_objmon_isinpool(inf)) failed: monitor is invalid 

I ran into this assertion failure:

#  Internal Error (/work/shared/bug_hunt/8047212_for_jdk9_hs_rt/hotspot/src/share/vm/gc/g1/vm_operations_g1.cpp:71), pid=3640, tid=3746
#  guarantee(target_pause_time_ms > 0.0) failed: target_pause_time_ms = -0.000000 should be positive
#
# JRE version: Java(TM) SE Runtime Environment (9.0) (build 1.9.0-internal-fastdebug-ddaugher_2015_10_15_17_35-b00)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (1.9.0-internal-fastdebug-ddaugher_2015_10_15_17_35-b00, mixed mode, tiered, compressed oops, g1 gc, linux-amd64)

Here is a snippet of the hs_err_pid file:

---------------  T H R E A D  ---------------

Current thread (0x00007f1efc318000):  JavaThread "Loading Thread #8" [_thread_in_vm, id=3746, stack(0x00007f1ee80fc000,0x00007f1ee81fd000)]
Stack: [0x00007f1ee80fc000,0x00007f1ee81fd000],  sp=0x00007f1ee81fae30,  free sp
ace=1019k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x113eec5]  VMError::report_and_die(int, char const*, char const*,
 __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsign
ed long)+0x155
V  [libjvm.so+0x113fbfa]  VMError::report_and_die(Thread*, char const*, int, cha
r const*, char const*, __va_list_tag*)+0x4a
V  [libjvm.so+0x82bfb4]  report_vm_error(char const*, int, char const*, char const*, ...)+0xd4
V  [libjvm.so+0x116cee8]  VM_G1IncCollectionPause::VM_G1IncCollectionPause(unsig
ned int, unsigned long, bool, double, GCCause::Cause)+0xa8
V  [libjvm.so+0x92f362]  G1CollectedHeap::do_collection_pause(unsigned long, unsigned int, bool*, GCCause::Cause)+0x172
V  [libjvm.so+0x92fcf4]  G1CollectedHeap::attempt_allocation_slow(unsigned long, unsigned char, unsigned int*, unsigned int*)+0x784
V  [libjvm.so+0x944fae]  G1CollectedHeap::attempt_allocation(unsigned long, unsi
gned int*, unsigned int*)+0x15e
V  [libjvm.so+0x9392c2]  G1CollectedHeap::allocate_new_tlab(unsigned long)+0x82
V  [libjvm.so+0x770371]  CollectedHeap::allocate_from_tlab_slow(KlassHandle, Thr
ead*, unsigned long)+0x1b1
V  [libjvm.so+0xa73068]  InstanceKlass::allocate_instance(Thread*)+0x608
V  [libjvm.so+0xa9fd14]  InterpreterRuntime::_new(JavaThread*, ConstantPool*, int)+0x2b4
j  sun.misc.URLClassPath.<init>([Ljava/net/URL;Ljava/net/URLStreamHandlerFactory;)V+38
j  sun.misc.URLClassPath.<init>([Ljava/net/URL;)V+3j  java.net.URLClassLoader.<init>([Ljava/net/URL;)V+33
j  runtime.ParallelClassLoading.shared.ProvokeType.provoke(Ljava/lang/ClassLoader;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)V+15
j  runtime.ParallelClassLoading.shared.CustomProvokeType.provoke(Ljava/lang/ClassLoader;Ljava/lang/String;)V+10
j  runtime.ParallelClassLoading.shared.ClassLoadingThread.run()V+83v  ~StubRoutines::call_stub
V  [libjvm.so+0xabf487]  JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)+0x17b7
V  [libjvm.so+0xabbf8a]  JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*)+0x61a
V  [libjvm.so+0xabc107]  JavaCalls::call_virtual(JavaValue*, Handle, KlassHandle, Symbol*, Symbol*, Thread*)+0xb7
V  [libjvm.so+0xb97934]  thread_entry(JavaThread*, Thread*)+0xc4
V  [libjvm.so+0x10c14b6]  JavaThread::thread_main_inner()+0x1d6
V  [libjvm.so+0x10c17e4]  JavaThread::run()+0x2a4
V  [libjvm.so+0xe8ea0a]  java_start(Thread*)+0xca
C  [libpthread.so.0+0x7851]

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j  sun.misc.URLClassPath.<init>([Ljava/net/URL;Ljava/net/URLStreamHandlerFactory;)V+38
j  sun.misc.URLClassPath.<init>([Ljava/net/URL;)V+3
j  java.net.URLClassLoader.<init>([Ljava/net/URL;)V+33
j  runtime.ParallelClassLoading.shared.ProvokeType.provoke(Ljava/lang/ClassLoader;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)V+15
j  runtime.ParallelClassLoading.shared.CustomProvokeType.provoke(Ljava/lang/ClassLoader;Ljava/lang/String;)V+10
j  runtime.ParallelClassLoading.shared.ClassLoadingThread.run()V+83
v  ~StubRoutines::call_stub


My baseline is a clone of RT_Baseline at the following fix: 

$ hg -R hotspot/ log -r tip
changeset:   9016:59e6f265dd40
tag:         tip
user:        aharlap
date:        Wed Sep 30 18:09:40 2015 -0400
summary:     8130265: gctests/LargeObjects/large001 fails with OutOfMemoryError: Java heap space

$ cat 2015-10-01-144936.jesper.8130265/SourceTips.txt 
 .:34280222936a jdk:8a9a7b1a3210 jaxp:497bc2654e11 pubs:618464525123 corba:ca8a17195884 jaxws:bdb954839363 closed:57176e80ab18 hotspot:59e6f265dd40 nashorn:678db05f13ba langtools:8e76163b3f3a jdk/src/closed:59bd18af2265 jdk/make/closed:54d0705354f2 jdk/test/closed:de2be51ab426 hotspot/src/closed:002bf5205dcd hotspot/make/closed:d70cd66cf2f4 hotspot/test/closed:5524c847f372

My testing config is running 4 parallel test runs using the following locally built bits:

$ /work/shared/bug_hunt/8047212_for_jdk9_hs_rt/build/linux-x86_64-normal-server-fastdebug/images/jdk/bin/java -version
java version "1.9.0-internal-fastdebug"
Java(TM) SE Runtime Environment (build 1.9.0-internal-fastdebug-ddaugher_2015_10_15_17_35-b00)
Java HotSpot(TM) 64-Bit Server VM (build 1.9.0-internal-fastdebug-ddaugher_2015_10_15_17_35-b00, mixed mode)

$ /work/shared/bug_hunt/8047212_for_jdk9_hs_rt/build/linux-x86_64-normal-server-fastdebug/images/jdk/bin/java -Xinternalversion
Java HotSpot(TM) 64-Bit Server VM (1.9.0-internal-fastdebug-ddaugher_2015_10_15_17_35-b00) for linux-amd64 JRE (1.9.0-internal-ddaugher_2015_10_15_17_35-b00), built on Oct 15 2015 18:09:47 by "ddaugher" with gcc 4.8.2

$ elapsed_times mark.start_test_run hs_err_pid3640.log
mark.start_test_run                      0 seconds
hs_err_pid3640.log  14 hours  3 minutes 14 seconds

I'm attaching hs_err_pid3640.log.
Comments
I did a very long stress run with the fix for JDK-8047212 in place on my Linux DevOps machine and on my local Solaris X64 server. This latest version was baselined on a JDK9-hs-rt repo as of this fix: Changeset: 9b74c5f1b10e Author: brutisso Date: 2015-10-20 14:00 +0200 URL: http://hg.openjdk.java.net/jdk9/hs-rt/hotspot/rev/9b74c5f1b10e 8139868: CMSScavengeBeforeRemark broken after JDK-8134953 Reviewed-by: sjohanss, jwilhelm Here's all the repo tip info: $ cat 2015-10-20-121401.brutisso.8139868/SourceTips.txt .:cd061b69a817 jdk:d68de0bab8ee jaxp:91795d86744f corba:1ee087da34d5 jaxws:51729143f8fe closed:bb694776dce5 hotspot:9b74c5f1b10e nashorn:d8936a4a0186 langtools:e6fcc24b6d14 jdk/src/closed:1056f5b75a9e jdk/make/closed:8498209d9810 jdk/test/closed:e93dd07f3dee hotspot/src/closed:e1b24390d910 hotspot/make/closed:7131ce6f91de hotspot/test/closed:4913ed0cb0cd So the bits tested are based on the above repo info plus the fix for JDK-8047212; the builds were done locally on the test machines. Linux DevOps machine: $ elapsed_times mark.start_test_run doit_loop.fast_0.log mark.start_test_run 0 seconds doit_loop.fast_0.log 6 days 20 hours 54 seconds $ grep -v PASS doit_loop.fast_?.log doit_loop.fast_0.log:Copy fast_0: loop #1019206... doit_loop.fast_1.log:Copy fast_1: loop #1019583... doit_loop.fast_2.log:Copy fast_2: loop #1019596... doit_loop.fast_3.log:Copy fast_3: loop #1019529... Solaris X64 machine: $ elapsed_times mark.start_test_run doit_loop.fast_0.log mark.start_test_run 0 seconds doit_loop.fast_0.log 6 days 21 hours 38 minutes 46 seconds $ grep -v PASS doit_loop.fast_?.log doit_loop.fast_0.log:Copy fast_0: loop #715125... doit_loop.fast_1.log:Copy fast_1: loop #714984... doit_loop.fast_2.log:Copy fast_2: loop #715051... doit_loop.fast_3.log:Copy fast_3: loop #715111... So the failure mode for this bug (JDK-8139937) is no longer reproducible in my Linux DevOps env. It was never reproducible in my Solaris X64 server environment. I can't explain why my fix JDK-8047212 would cause this bug to go away so I'm not going to close this bug. However, if someone on the GC team wants to close this bug as "not reproducible", I would have no objections.
27-10-2015

That is an interesting issue indeed, you didn't happen to catch a core file? The value which is passed to target_pause_time_ms is only set up once, based on -XX:MaxGCPauseMillis which has a default value of 200 and is prohibited from being 0. Getting a "-0.0" double value almost smells like a bug in passing floating point arguments or preserving floating point registers....
21-10-2015