JDK-8211211 : vmTestbase/metaspace/stressDictionary/StressDictionary.java timeout
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 12
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2018-09-27
  • Updated: 2021-04-01
  • Resolved: 2018-11-28
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 11 JDK 12
11.0.7-oracleFixed 12 b22Fixed
Related Reports
Relates :  
Sub Tasks
JDK-8212220 :  
JDK-8213704 :  
Description
----------System.out:(1258/89045)----------
Stress time: 30 seconds
Stress iterations factor: 1
Stress threads factor: 1
Stress runs factor: 1
Max memory: 2481061888
Sleep time: 500
Iterations: 0
Number of threads: 12
Seed: 1538034001360
Run GC thread: false
Run mem diag thread: false
Run forever: false
Timeout refired 1200 times
2018-09-27 01:01:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.520 mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f45b40075e0, length=33, elements={
0x00007f45f401d800, 0x00007f45f4231800, 0x00007f45f4237800, 0x00007f45f4289000,
0x00007f45f428c000, 0x00007f45f428e800, 0x00007f45f4291000, 0x00007f45f4359000,
0x00007f45f4381000, 0x00007f45f4440800, 0x00007f45a05dc800, 0x00007f45a05de800,
0x00007f45a05e0800, 0x00007f45a05e3000, 0x00007f45a05e5000, 0x00007f45a05e7000,
0x00007f45a05e9800, 0x00007f45a05eb800, 0x00007f45a05ee000, 0x00007f45a05f0000,
0x00007f45a05f2800, 0x00007f45a05f4800, 0x00007f45a05f6800, 0x00007f45a07ae800,
0x00007f45a07b1000, 0x00007f45a07b3800, 0x00007f45a07b6000, 0x00007f45a07b8000,
0x00007f45a07ba800, 0x00007f45a07bd000, 0x00007f45b4001000, 0x00007f45b4003000,
0x00007f45b4005800
}
_java_thread_list_alloc_cnt=36, _java_thread_list_free_cnt=35, _java_thread_list_max=33, _nested_thread_list_max=1
_tlh_cnt=1914, _tlh_times=11, avg_tlh_time=0.01, _tlh_time_max=6
_deleted_thread_cnt=1, _deleted_thread_times=0, avg_deleted_thread_time=0.00, _deleted_thread_time_max=0
_delete_lock_wait_cnt=0, _delete_lock_wait_max=0
_to_delete_list_cnt=0, _to_delete_list_max=1

"main" #1 prio=5 os_prio=0 cpu=1064.84ms elapsed=1317.51s tid=0x00007f45f401d800 nid=0x290b in Object.wait()  [0x00007f45fc444000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f401d800  [0x290b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000770f89580> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-internal/Thread.java:1308)
	- waiting to re-lock in wait() <0x0000000770f89580> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-internal/Thread.java:1375)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=2.44ms elapsed=1316.42s tid=0x00007f45f4231800 nid=0x2911 waiting on condition  [0x00007f45d2a2a000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4231800  [0x2911] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@12-internal/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@12-internal/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@12-internal/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=7.87ms elapsed=1316.41s tid=0x00007f45f4237800 nid=0x2912 in Object.wait()  [0x00007f45d2929000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4237800  [0x2912] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@12-internal/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=1.32ms elapsed=1316.31s tid=0x00007f45f4289000 nid=0x2913 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4289000  [0x2913] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=2107.20ms elapsed=1316.30s tid=0x00007f45f428c000 nid=0x2914 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428c000  [0x2914] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=3096.97ms elapsed=1316.29s tid=0x00007f45f428e800 nid=0x2915 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428e800  [0x2915] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #8 daemon prio=9 os_prio=0 cpu=13.07ms elapsed=1316.28s tid=0x00007f45f4291000 nid=0x2916 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4291000  [0x2916] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Service Thread" #9 daemon prio=9 os_prio=0 cpu=6.47ms elapsed=1316.00s tid=0x00007f45f4359000 nid=0x2917 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4359000  [0x2917] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #10 daemon prio=8 os_prio=0 cpu=2.23ms elapsed=1315.93s tid=0x00007f45f4381000 nid=0x2919 runnable  [0x00007f45d2222000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4381000  [0x2919] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.ref.PhantomCleanable.remove(java.base@12-internal/PhantomCleanable.java:102)
	at jdk.internal.ref.PhantomCleanable.clean(java.base@12-internal/PhantomCleanable.java:131)
	at jdk.internal.ref.CleanerImpl.run(java.base@12-internal/CleanerImpl.java:150)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)
	at jdk.internal.misc.InnocuousThread.run(java.base@12-internal/InnocuousThread.java:134)

"MainThread" #12 prio=5 os_prio=0 cpu=3162.82ms elapsed=1315.70s tid=0x00007f45f4440800 nid=0x291a waiting on condition  [0x00007f45d1cc7000]
   java.lang.Thread.State: WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4440800  [0x291a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x00000007711efae0> (a java.util.concurrent.FutureTask)
	at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194)
	at java.util.concurrent.FutureTask.awaitDone(java.base@12-internal/FutureTask.java:447)
	at java.util.concurrent.FutureTask.get(java.base@12-internal/FutureTask.java:190)
	at java.util.concurrent.AbstractExecutorService.invokeAll(java.base@12-internal/AbstractExecutorService.java:247)
	at metaspace.stressDictionary.StressDictionary.run(StressDictionary.java:127)
	at nsk.share.test.Tests$TestRunner.execute(Tests.java:82)
	at nsk.share.test.Tests$TestRunner.run(Tests.java:96)
	at nsk.share.test.Tests.runTest(Tests.java:102)
	at metaspace.stressDictionary.StressDictionary.main(StressDictionary.java:109)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@12-internal/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@12-internal/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@12-internal/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@12-internal/Method.java:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-1" #13 prio=5 os_prio=0 cpu=1480.38ms elapsed=1312.33s tid=0x00007f45a05dc800 nid=0x2936 waiting for monitor entry  [0x00007f45d12c6000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05dc800  [0x2936] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-2" #14 prio=5 os_prio=0 cpu=1454.51ms elapsed=1312.33s tid=0x00007f45a05de800 nid=0x2937 waiting for monitor entry  [0x00007f45d11c5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05de800  [0x2937] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-3" #15 prio=5 os_prio=0 cpu=1887.80ms elapsed=1312.33s tid=0x00007f45a05e0800 nid=0x2938 waiting for monitor entry  [0x00007f45d10c4000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e0800  [0x2938] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-4" #16 prio=5 os_prio=0 cpu=1779.15ms elapsed=1312.33s tid=0x00007f45a05e3000 nid=0x2939 runnable  [0x00007f45d0fc3000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e3000  [0x2939] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.util.concurrent.SynchronousQueue$TransferStack.shouldSpin(java.base@12-internal/SynchronousQueue.java:471)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:455)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-5" #17 prio=5 os_prio=0 cpu=1752.92ms elapsed=1312.33s tid=0x00007f45a05e5000 nid=0x293a runnable  [0x00007f45d0ec2000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e5000  [0x293a] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-6" #18 prio=5 os_prio=0 cpu=1796.16ms elapsed=1312.33s tid=0x00007f45a05e7000 nid=0x293b waiting for monitor entry  [0x00007f45d0dc1000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e7000  [0x293b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-7" #19 prio=5 os_prio=0 cpu=1481.51ms elapsed=1312.32s tid=0x00007f45a05e9800 nid=0x293c waiting for monitor entry  [0x00007f45d0cc0000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e9800  [0x293c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-8" #20 prio=5 os_prio=0 cpu=1937.67ms elapsed=1312.32s tid=0x00007f45a05eb800 nid=0x293d waiting for monitor entry  [0x00007f45d0bbf000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05eb800  [0x293d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-9" #21 prio=5 os_prio=0 cpu=1527.32ms elapsed=1312.32s tid=0x00007f45a05ee000 nid=0x293e waiting for monitor entry  [0x00007f45d0abe000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05ee000  [0x293e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-10" #22 prio=5 os_prio=0 cpu=1907.46ms elapsed=1312.32s tid=0x00007f45a05f0000 nid=0x293f waiting for monitor entry  [0x00007f45d09bd000]
   java.lang.Thread.State: BLOCKED (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f0000  [0x293f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016)
	at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877)
	at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35)
	at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69)
	at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-11" #23 prio=5 os_prio=0 cpu=2.16ms elapsed=1312.32s tid=0x00007f45a05f2800 nid=0x2940 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f2800  [0x2940] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-12" #24 prio=5 os_prio=0 cpu=1.78ms elapsed=1312.32s tid=0x00007f45a05f4800 nid=0x2941 waiting on condition  [0x00007f45d07ba000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f4800  [0x2941] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.util.concurrent.ConcurrentHashMap.replaceNode(java.base@12-internal/ConcurrentHashMap.java:1122)
	- locked <0x0000000770ed08c0> (a java.util.concurrent.ConcurrentHashMap$Node)
	at java.util.concurrent.ConcurrentHashMap.remove(java.base@12-internal/ConcurrentHashMap.java:1102)
	at java.lang.invoke.MethodType$ConcurrentWeakInternSet.expungeStaleElements(java.base@12-internal/MethodType.java:1344)
	at java.lang.invoke.MethodType$ConcurrentWeakInternSet.get(java.base@12-internal/MethodType.java:1303)
	at java.lang.invoke.MethodType.makeImpl(java.base@12-internal/MethodType.java:299)
	at java.lang.invoke.MethodHandleNatives.findMethodHandleType(java.base@12-internal/MethodHandleNatives.java:376)
	at java.util.concurrent.SynchronousQueue$TransferStack$SNode.tryCancel(java.base@12-internal/SynchronousQueue.java:280)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:449)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-13" #25 prio=5 os_prio=0 cpu=1.82ms elapsed=1312.32s tid=0x00007f45a05f6800 nid=0x2942 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f6800  [0x2942] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-14" #26 prio=5 os_prio=0 cpu=1.33ms elapsed=1312.32s tid=0x00007f45a07ae800 nid=0x2943 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07ae800  [0x2943] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-15" #27 prio=5 os_prio=0 cpu=1.35ms elapsed=1312.32s tid=0x00007f45a07b1000 nid=0x2944 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07b1000  [0x2944] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-16" #28 prio=5 os_prio=0 cpu=1.29ms elapsed=1312.32s tid=0x00007f45a07b3800 nid=0x2945 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07b3800  [0x2945] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-17" #29 prio=5 os_prio=0 cpu=1.24ms elapsed=1312.32s tid=0x00007f45a07b6000 nid=0x2946 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07b6000  [0x2946] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-18" #30 prio=5 os_prio=0 cpu=2.11ms elapsed=1312.32s tid=0x00007f45a07b8000 nid=0x2947 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07b8000  [0x2947] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"pool-1-thread-19" #31 prio=5 os_prio=0 cpu=3.14ms elapsed=1312.32s tid=0x00007f45a07ba800 nid=0x2948 runnable  [0x00007f4553ffd000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07ba800  [0x2948] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.util.HashMap.remove(java.base@12-internal/HashMap.java:794)
	at java.util.HashSet.remove(java.base@12-internal/HashSet.java:236)
	at java.util.concurrent.ThreadPoolExecutor.processWorkerExit(java.base@12-internal/ThreadPoolExecutor.java:989)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-20" #32 prio=5 os_prio=0 cpu=2.11ms elapsed=1312.32s tid=0x00007f45a07bd000 nid=0x2949 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45a07bd000  [0x2949] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #33 daemon prio=9 os_prio=0 cpu=0.28ms elapsed=0.05s tid=0x00007f45b4001000 nid=0x339d runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4001000  [0x339d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #34 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=0.05s tid=0x00007f45b4003000 nid=0x339e runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4003000  [0x339e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #35 daemon prio=9 os_prio=0 cpu=0.21ms elapsed=0.05s tid=0x00007f45b4005800 nid=0x339f runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4005800  [0x339f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"VM Thread" os_prio=0 cpu=1297349.79ms elapsed=1316.49s tid=0x00007f45f4213000 nid=0x2910 runnable  

"GC Thread#0" os_prio=0 cpu=150.86ms elapsed=1317.51s tid=0x00007f45f4045800 nid=0x290c runnable  

"GC Thread#1" os_prio=0 cpu=55.77ms elapsed=1307.21s tid=0x00007f45c8003000 nid=0x294c runnable  

"GC Thread#2" os_prio=0 cpu=43.10ms elapsed=1307.21s tid=0x00007f45c8005000 nid=0x294d runnable  

"GC Thread#3" os_prio=0 cpu=54.89ms elapsed=1307.21s tid=0x00007f45c8006800 nid=0x294e runnable  

"GC Thread#4" os_prio=0 cpu=55.50ms elapsed=1307.21s tid=0x00007f45c8008800 nid=0x294f runnable  

"GC Thread#5" os_prio=0 cpu=52.90ms elapsed=1307.21s tid=0x00007f45c800a800 nid=0x2950 runnable  

"CMS Main Thread" os_prio=0 cpu=2116.06ms elapsed=1316.69s tid=0x00007f45f40b1000 nid=0x290f runnable  

"CMS Thread#0" os_prio=0 cpu=0.42ms elapsed=1316.72s tid=0x00007f45f40ad800 nid=0x290e runnable  

"CMS Thread#1" os_prio=0 cpu=0.36ms elapsed=1310.20s tid=0x00007f45c4001000 nid=0x294a runnable  

"VM Periodic Task Thread" os_prio=0 cpu=1624.06ms elapsed=1315.98s tid=0x00007f45f436b000 nid=0x2918 waiting on condition  

JNI global refs: 8, weak refs: 0

Heap
 par new generation   total 145024K, used 15196K [0x0000000769000000, 0x0000000772d50000, 0x0000000788330000)
  eden space 128960K,   7% used [0x0000000769000000, 0x000000076991e500, 0x0000000770df0000)
  from space 16064K,  36% used [0x0000000770df0000, 0x00000007713a8b50, 0x0000000771da0000)
  to   space 16064K,   0% used [0x0000000771da0000, 0x0000000771da0000, 0x0000000772d50000)
 concurrent mark-sweep generation total 322240K, used 0K [0x0000000788330000, 0x000000079bde0000, 0x0000000800000000)
 Metaspace       used 100850K, capacity 101464K, committed 103556K, reserved 1124352K
  class space    used 28097K, capacity 28358K, committed 28468K, reserved 1048576K

2018-09-27 01:01:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.520 mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f4564000c60, length=23, elements={
0x00007f45f401d800, 0x00007f45f4231800, 0x00007f45f4237800, 0x00007f45f4289000,
0x00007f45f428c000, 0x00007f45f428e800, 0x00007f45f4291000, 0x00007f45f4359000,
0x00007f45f4381000, 0x00007f45f4440800, 0x00007f45a05dc800, 0x00007f45a05de800,
0x00007f45a05e0800, 0x00007f45a05e3000, 0x00007f45a05e5000, 0x00007f45a05e7000,
0x00007f45a05e9800, 0x00007f45a05eb800, 0x00007f45a05ee000, 0x00007f45a05f0000,
0x00007f45b4001000, 0x00007f45b4003000, 0x00007f45b4005800
}
_to_delete_list=0x00007f4548000f30, length=24, elements={
0x00007f45f401d800, 0x00007f45f4231800, 0x00007f45f4237800, 0x00007f45f4289000,
0x00007f45f428c000, 0x00007f45f428e800, 0x00007f45f4291000, 0x00007f45f4359000,
0x00007f45f4381000, 0x00007f45f4440800, 0x00007f45a05dc800, 0x00007f45a05de800,
0x00007f45a05e0800, 0x00007f45a05e3000, 0x00007f45a05e5000, 0x00007f45a05e7000,
0x00007f45a05e9800, 0x00007f45a05eb800, 0x00007f45a05ee000, 0x00007f45a05f0000,
0x00007f45a05f4800, 0x00007f45b4001000, 0x00007f45b4003000, 0x00007f45b4005800
}
_java_thread_list_alloc_cnt=46, _java_thread_list_free_cnt=44, _java_thread_list_max=33, _nested_thread_list_max=1
_tlh_cnt=1969, _tlh_times=11, avg_tlh_time=0.01, _tlh_time_max=6
_deleted_thread_cnt=9, _deleted_thread_times=0, avg_deleted_thread_time=0.00, _deleted_thread_time_max=0
_delete_lock_wait_cnt=0, _delete_lock_wait_max=1
_to_delete_list_cnt=1, _to_delete_list_max=1

"main" #1 prio=5 os_prio=0 cpu=1064.84ms elapsed=1317.68s tid=0x00007f45f401d800 nid=0x290b in Object.wait()  [0x00007f45fc444000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f401d800  [0x290b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000770f89580> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-internal/Thread.java:1308)
	- waiting to re-lock in wait() <0x0000000770f89580> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-internal/Thread.java:1375)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=2.44ms elapsed=1316.59s tid=0x00007f45f4231800 nid=0x2911 waiting on condition  [0x00007f45d2a2a000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4231800  [0x2911] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@12-internal/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@12-internal/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@12-internal/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=7.87ms elapsed=1316.58s tid=0x00007f45f4237800 nid=0x2912 in Object.wait()  [0x00007f45d2929000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4237800  [0x2912] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@12-internal/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=1.53ms elapsed=1316.48s tid=0x00007f45f4289000 nid=0x2913 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4289000  [0x2913] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=2107.23ms elapsed=1316.47s tid=0x00007f45f428c000 nid=0x2914 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428c000  [0x2914] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=3098.21ms elapsed=1316.46s tid=0x00007f45f428e800 nid=0x2915 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428e800  [0x2915] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   Compiling: 1467       3       java.util.concurrent.SynchronousQueue$TransferStack::shouldSpin (30 bytes)

"Sweeper thre

...
Output overflow:
JT Harness has limited the test output to the text to that
at the beginning and the end, so that you can see how the
test began, and how it completed.

If you need to see more of the output from the test,
set the system property javatest.maxOutputSize to a higher
value. The current value is 100000
...

 to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-7" #19 prio=5 os_prio=0 cpu=1488.88ms elapsed=1312.85s tid=0x00007f45a05e9800 nid=0x293c waiting on condition  [0x00007f45d0cc0000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e9800  [0x293c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-8" #20 prio=5 os_prio=0 cpu=2012.20ms elapsed=1312.85s tid=0x00007f45a05eb800 nid=0x293d waiting on condition  [0x00007f45d0bbf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05eb800  [0x293d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-9" #21 prio=5 os_prio=0 cpu=1598.22ms elapsed=1312.85s tid=0x00007f45a05ee000 nid=0x293e waiting on condition  [0x00007f45d0abe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05ee000  [0x293e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-10" #22 prio=5 os_prio=0 cpu=1950.87ms elapsed=1312.85s tid=0x00007f45a05f0000 nid=0x293f waiting on condition  [0x00007f45d09bd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f0000  [0x293f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"Attach Listener" #33 daemon prio=9 os_prio=0 cpu=0.28ms elapsed=0.58s tid=0x00007f45b4001000 nid=0x339d runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4001000  [0x339d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #34 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=0.58s tid=0x00007f45b4003000 nid=0x339e runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4003000  [0x339e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #35 daemon prio=9 os_prio=0 cpu=13.70ms elapsed=0.58s tid=0x00007f45b4005800 nid=0x339f runnable  [0x00007f452fbfc000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4005800  [0x339f] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.util.Date.toString(java.base@12-internal/Date.java:1042)
	at java.util.Properties.store0(java.base@12-internal/Properties.java:908)
	at java.util.Properties.store(java.base@12-internal/Properties.java:897)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:70)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:75)

"VM Thread" os_prio=0 cpu=1297455.87ms elapsed=1317.01s tid=0x00007f45f4213000 nid=0x2910 runnable  

"GC Thread#0" os_prio=0 cpu=150.86ms elapsed=1318.04s tid=0x00007f45f4045800 nid=0x290c runnable  

"GC Thread#1" os_prio=0 cpu=55.77ms elapsed=1307.74s tid=0x00007f45c8003000 nid=0x294c runnable  

"GC Thread#2" os_prio=0 cpu=43.10ms elapsed=1307.74s tid=0x00007f45c8005000 nid=0x294d runnable  

"GC Thread#3" os_prio=0 cpu=54.89ms elapsed=1307.74s tid=0x00007f45c8006800 nid=0x294e runnable  

"GC Thread#4" os_prio=0 cpu=55.50ms elapsed=1307.74s tid=0x00007f45c8008800 nid=0x294f runnable  

"GC Thread#5" os_prio=0 cpu=52.90ms elapsed=1307.74s tid=0x00007f45c800a800 nid=0x2950 runnable  

"CMS Main Thread" os_prio=0 cpu=2117.43ms elapsed=1317.22s tid=0x00007f45f40b1000 nid=0x290f runnable  

"CMS Thread#0" os_prio=0 cpu=0.42ms elapsed=1317.24s tid=0x00007f45f40ad800 nid=0x290e runnable  

"CMS Thread#1" os_prio=0 cpu=0.36ms elapsed=1310.73s tid=0x00007f45c4001000 nid=0x294a runnable  

"VM Periodic Task Thread" os_prio=0 cpu=1624.46ms elapsed=1316.50s tid=0x00007f45f436b000 nid=0x2918 waiting on condition  

JNI global refs: 8, weak refs: 0

Heap
 par new generation   total 145024K, used 24935K [0x0000000769000000, 0x0000000772d50000, 0x0000000788330000)
  eden space 128960K,  14% used [0x0000000769000000, 0x000000076a2a11a0, 0x0000000770df0000)
  from space 16064K,  36% used [0x0000000770df0000, 0x00000007713a8b50, 0x0000000771da0000)
  to   space 16064K,   0% used [0x0000000771da0000, 0x0000000771da0000, 0x0000000772d50000)
 concurrent mark-sweep generation total 322240K, used 0K [0x0000000788330000, 0x000000079bde0000, 0x0000000800000000)
 Metaspace       used 100939K, capacity 101528K, committed 103812K, reserved 1124352K
  class space    used 28109K, capacity 28358K, committed 28468K, reserved 1048576K

2018-09-27 01:01:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.520 mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f45a07ac1c0, length=22, elements={
0x00007f45f401d800, 0x00007f45f4231800, 0x00007f45f4237800, 0x00007f45f4289000,
0x00007f45f428c000, 0x00007f45f428e800, 0x00007f45f4291000, 0x00007f45f4359000,
0x00007f45f4381000, 0x00007f45a05dc800, 0x00007f45a05de800, 0x00007f45a05e0800,
0x00007f45a05e3000, 0x00007f45a05e5000, 0x00007f45a05e7000, 0x00007f45a05e9800,
0x00007f45a05eb800, 0x00007f45a05ee000, 0x00007f45a05f0000, 0x00007f45b4001000,
0x00007f45b4003000, 0x00007f45b4005800
}
_java_thread_list_alloc_cnt=47, _java_thread_list_free_cnt=46, _java_thread_list_max=33, _nested_thread_list_max=1
_tlh_cnt=2546, _tlh_times=11, avg_tlh_time=0.00, _tlh_time_max=6
_deleted_thread_cnt=12, _deleted_thread_times=206, avg_deleted_thread_time=17.17, _deleted_thread_time_max=123
_delete_lock_wait_cnt=0, _delete_lock_wait_max=1
_to_delete_list_cnt=0, _to_delete_list_max=2

"main" #1 prio=5 os_prio=0 cpu=1073.22ms elapsed=1318.04s tid=0x00007f45f401d800 nid=0x290b runnable  [0x00007f45fc444000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f401d800  [0x290b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Shutdown.halt0(java.base@12-internal/Native Method)
	at java.lang.Shutdown.halt(java.base@12-internal/Shutdown.java:152)
	- locked <0x000000076a1329f8> (a java.lang.Shutdown$Lock)
	at java.lang.Shutdown.exit(java.base@12-internal/Shutdown.java:175)
	- locked <0x000000076a132878> (a java.lang.Class for java.lang.Shutdown)
	at java.lang.Runtime.exit(java.base@12-internal/Runtime.java:115)
	at java.lang.System.exit(java.base@12-internal/System.java:1746)
	at com.sun.javatest.regtest.agent.AStatus.exit(AStatus.java:199)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:84)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=2.44ms elapsed=1316.95s tid=0x00007f45f4231800 nid=0x2911 waiting on condition  [0x00007f45d2a2a000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4231800  [0x2911] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@12-internal/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@12-internal/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@12-internal/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=7.87ms elapsed=1316.94s tid=0x00007f45f4237800 nid=0x2912 in Object.wait()  [0x00007f45d2929000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4237800  [0x2912] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@12-internal/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=5.45ms elapsed=1316.85s tid=0x00007f45f4289000 nid=0x2913 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4289000  [0x2913] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=2107.28ms elapsed=1316.84s tid=0x00007f45f428c000 nid=0x2914 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428c000  [0x2914] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=3103.06ms elapsed=1316.83s tid=0x00007f45f428e800 nid=0x2915 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428e800  [0x2915] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #8 daemon prio=9 os_prio=0 cpu=13.07ms elapsed=1316.82s tid=0x00007f45f4291000 nid=0x2916 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4291000  [0x2916] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Service Thread" #9 daemon prio=9 os_prio=0 cpu=6.47ms elapsed=1316.54s tid=0x00007f45f4359000 nid=0x2917 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4359000  [0x2917] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #10 daemon prio=8 os_prio=0 cpu=2.28ms elapsed=1316.46s tid=0x00007f45f4381000 nid=0x2919 in Object.wait()  [0x00007f45d2222000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4381000  [0x2919] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771056650> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771056650> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@12-internal/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)
	at jdk.internal.misc.InnocuousThread.run(java.base@12-internal/InnocuousThread.java:134)

"pool-1-thread-1" #13 prio=5 os_prio=0 cpu=1551.25ms elapsed=1312.86s tid=0x00007f45a05dc800 nid=0x2936 waiting on condition  [0x00007f45d12c6000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05dc800  [0x2936] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-2" #14 prio=5 os_prio=0 cpu=1498.87ms elapsed=1312.86s tid=0x00007f45a05de800 nid=0x2937 waiting on condition  [0x00007f45d11c5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05de800  [0x2937] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-3" #15 prio=5 os_prio=0 cpu=1888.57ms elapsed=1312.86s tid=0x00007f45a05e0800 nid=0x2938 waiting on condition  [0x00007f45d10c4000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e0800  [0x2938] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-4" #16 prio=5 os_prio=0 cpu=1779.33ms elapsed=1312.86s tid=0x00007f45a05e3000 nid=0x2939 waiting on condition  [0x00007f45d0fc3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e3000  [0x2939] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-5" #17 prio=5 os_prio=0 cpu=1798.51ms elapsed=1312.86s tid=0x00007f45a05e5000 nid=0x293a waiting on condition  [0x00007f45d0ec2000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e5000  [0x293a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-6" #18 prio=5 os_prio=0 cpu=1838.23ms elapsed=1312.86s tid=0x00007f45a05e7000 nid=0x293b waiting on condition  [0x00007f45d0dc1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e7000  [0x293b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-7" #19 prio=5 os_prio=0 cpu=1488.88ms elapsed=1312.86s tid=0x00007f45a05e9800 nid=0x293c waiting on condition  [0x00007f45d0cc0000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e9800  [0x293c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-8" #20 prio=5 os_prio=0 cpu=2012.20ms elapsed=1312.86s tid=0x00007f45a05eb800 nid=0x293d waiting on condition  [0x00007f45d0bbf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05eb800  [0x293d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-9" #21 prio=5 os_prio=0 cpu=1598.22ms elapsed=1312.86s tid=0x00007f45a05ee000 nid=0x293e waiting on condition  [0x00007f45d0abe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05ee000  [0x293e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-10" #22 prio=5 os_prio=0 cpu=1950.87ms elapsed=1312.86s tid=0x00007f45a05f0000 nid=0x293f waiting on condition  [0x00007f45d09bd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f0000  [0x293f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"Attach Listener" #33 daemon prio=9 os_prio=0 cpu=0.28ms elapsed=0.59s tid=0x00007f45b4001000 nid=0x339d runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4001000  [0x339d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #34 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=0.58s tid=0x00007f45b4003000 nid=0x339e runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4003000  [0x339e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #35 daemon prio=9 os_prio=0 cpu=16.55ms elapsed=0.58s tid=0x00007f45b4005800 nid=0x339f runnable  [0x00007f452fbfc000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4005800  [0x339f] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNamesImpl(java.base@12-internal/TimeZoneNameUtility.java:177)
	at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayName(java.base@12-internal/TimeZoneNameUtility.java:150)
	at java.util.TimeZone.getDisplayName(java.base@12-internal/TimeZone.java:401)
	at java.util.Date.toString(java.base@12-internal/Date.java:1046)
	at java.util.Properties.store0(java.base@12-internal/Properties.java:908)
	at java.util.Properties.store(java.base@12-internal/Properties.java:897)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:70)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:75)

"VM Thread" os_prio=0 cpu=1297459.65ms elapsed=1317.02s tid=0x00007f45f4213000 nid=0x2910 runnable  

"GC Thread#0" os_prio=0 cpu=150.86ms elapsed=1318.04s tid=0x00007f45f4045800 nid=0x290c runnable  

"GC Thread#1" os_prio=0 cpu=55.77ms elapsed=1307.74s tid=0x00007f45c8003000 nid=0x294c runnable  

"GC Thread#2" os_prio=0 cpu=43.10ms elapsed=1307.74s tid=0x00007f45c8005000 nid=0x294d runnable  

"GC Thread#3" os_prio=0 cpu=54.89ms elapsed=1307.74s tid=0x00007f45c8006800 nid=0x294e runnable  

"GC Thread#4" os_prio=0 cpu=55.50ms elapsed=1307.74s tid=0x00007f45c8008800 nid=0x294f runnable  

"GC Thread#5" os_prio=0 cpu=52.90ms elapsed=1307.74s tid=0x00007f45c800a800 nid=0x2950 runnable  

"CMS Main Thread" os_prio=0 cpu=2117.47ms elapsed=1317.23s tid=0x00007f45f40b1000 nid=0x290f runnable  

"CMS Thread#0" os_prio=0 cpu=0.42ms elapsed=1317.25s tid=0x00007f45f40ad800 nid=0x290e runnable  

"CMS Thread#1" os_prio=0 cpu=0.36ms elapsed=1310.74s tid=0x00007f45c4001000 nid=0x294a runnable  

"VM Periodic Task Thread" os_prio=0 cpu=1624.46ms elapsed=1316.51s tid=0x00007f45f436b000 nid=0x2918 waiting on condition  

JNI global refs: 8, weak refs: 0

Heap
 par new generation   total 145024K, used 24935K [0x0000000769000000, 0x0000000772d50000, 0x0000000788330000)
  eden space 128960K,  14% used [0x0000000769000000, 0x000000076a2a11a0, 0x0000000770df0000)
  from space 16064K,  36% used [0x0000000770df0000, 0x00000007713a8b50, 0x0000000771da0000)
  to   space 16064K,   0% used [0x0000000771da0000, 0x0000000771da0000, 0x0000000772d50000)
 concurrent mark-sweep generation total 322240K, used 0K [0x0000000788330000, 0x000000079bde0000, 0x0000000800000000)
 Metaspace       used 100954K, capacity 101528K, committed 103812K, reserved 1124352K
  class space    used 28110K, capacity 28358K, committed 28468K, reserved 1048576K

2018-09-27 01:01:57
Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.520 mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f45a07ac1c0, length=22, elements={
0x00007f45f401d800, 0x00007f45f4231800, 0x00007f45f4237800, 0x00007f45f4289000,
0x00007f45f428c000, 0x00007f45f428e800, 0x00007f45f4291000, 0x00007f45f4359000,
0x00007f45f4381000, 0x00007f45a05dc800, 0x00007f45a05de800, 0x00007f45a05e0800,
0x00007f45a05e3000, 0x00007f45a05e5000, 0x00007f45a05e7000, 0x00007f45a05e9800,
0x00007f45a05eb800, 0x00007f45a05ee000, 0x00007f45a05f0000, 0x00007f45b4001000,
0x00007f45b4003000, 0x00007f45b4005800
}
_java_thread_list_alloc_cnt=47, _java_thread_list_free_cnt=46, _java_thread_list_max=33, _nested_thread_list_max=1
_tlh_cnt=2561, _tlh_times=11, avg_tlh_time=0.00, _tlh_time_max=6
_deleted_thread_cnt=12, _deleted_thread_times=206, avg_deleted_thread_time=17.17, _deleted_thread_time_max=123
_delete_lock_wait_cnt=0, _delete_lock_wait_max=1
_to_delete_list_cnt=0, _to_delete_list_max=2

"main" #1 prio=5 os_prio=0 cpu=1077.75ms elapsed=1318.05s tid=0x00007f45f401d800 nid=0x290b runnable  [0x00007f45fc444000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f401d800  [0x290b] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Shutdown.halt0(java.base@12-internal/Native Method)
	at java.lang.Shutdown.halt(java.base@12-internal/Shutdown.java:152)
	- locked <0x000000076a1329f8> (a java.lang.Shutdown$Lock)
	at java.lang.Shutdown.exit(java.base@12-internal/Shutdown.java:175)
	- locked <0x000000076a132878> (a java.lang.Class for java.lang.Shutdown)
	at java.lang.Runtime.exit(java.base@12-internal/Runtime.java:115)
	at java.lang.System.exit(java.base@12-internal/System.java:1746)
	at com.sun.javatest.regtest.agent.AStatus.exit(AStatus.java:199)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:84)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=2.44ms elapsed=1316.96s tid=0x00007f45f4231800 nid=0x2911 waiting on condition  [0x00007f45d2a2a000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4231800  [0x2911] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@12-internal/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@12-internal/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@12-internal/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=7.87ms elapsed=1316.95s tid=0x00007f45f4237800 nid=0x2912 in Object.wait()  [0x00007f45d2929000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4237800  [0x2912] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771122c80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@12-internal/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=5.58ms elapsed=1316.86s tid=0x00007f45f4289000 nid=0x2913 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4289000  [0x2913] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=2107.28ms elapsed=1316.85s tid=0x00007f45f428c000 nid=0x2914 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428c000  [0x2914] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=3103.06ms elapsed=1316.83s tid=0x00007f45f428e800 nid=0x2915 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f428e800  [0x2915] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #8 daemon prio=9 os_prio=0 cpu=13.07ms elapsed=1316.82s tid=0x00007f45f4291000 nid=0x2916 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4291000  [0x2916] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Service Thread" #9 daemon prio=9 os_prio=0 cpu=6.47ms elapsed=1316.55s tid=0x00007f45f4359000 nid=0x2917 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4359000  [0x2917] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #10 daemon prio=8 os_prio=0 cpu=2.28ms elapsed=1316.47s tid=0x00007f45f4381000 nid=0x2919 in Object.wait()  [0x00007f45d2222000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00007f45f4381000  [0x2919] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-internal/Native Method)
	- waiting on <0x0000000771056650> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x0000000771056650> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@12-internal/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)
	at jdk.internal.misc.InnocuousThread.run(java.base@12-internal/InnocuousThread.java:134)

"pool-1-thread-1" #13 prio=5 os_prio=0 cpu=1551.25ms elapsed=1312.87s tid=0x00007f45a05dc800 nid=0x2936 waiting on condition  [0x00007f45d12c6000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05dc800  [0x2936] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-2" #14 prio=5 os_prio=0 cpu=1498.87ms elapsed=1312.87s tid=0x00007f45a05de800 nid=0x2937 waiting on condition  [0x00007f45d11c5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05de800  [0x2937] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-3" #15 prio=5 os_prio=0 cpu=1888.57ms elapsed=1312.87s tid=0x00007f45a05e0800 nid=0x2938 waiting on condition  [0x00007f45d10c4000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e0800  [0x2938] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-4" #16 prio=5 os_prio=0 cpu=1779.33ms elapsed=1312.87s tid=0x00007f45a05e3000 nid=0x2939 waiting on condition  [0x00007f45d0fc3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e3000  [0x2939] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-5" #17 prio=5 os_prio=0 cpu=1798.51ms elapsed=1312.87s tid=0x00007f45a05e5000 nid=0x293a waiting on condition  [0x00007f45d0ec2000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e5000  [0x293a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-6" #18 prio=5 os_prio=0 cpu=1838.23ms elapsed=1312.87s tid=0x00007f45a05e7000 nid=0x293b waiting on condition  [0x00007f45d0dc1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e7000  [0x293b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-7" #19 prio=5 os_prio=0 cpu=1488.88ms elapsed=1312.87s tid=0x00007f45a05e9800 nid=0x293c waiting on condition  [0x00007f45d0cc0000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05e9800  [0x293c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-8" #20 prio=5 os_prio=0 cpu=2012.20ms elapsed=1312.87s tid=0x00007f45a05eb800 nid=0x293d waiting on condition  [0x00007f45d0bbf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05eb800  [0x293d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-9" #21 prio=5 os_prio=0 cpu=1598.22ms elapsed=1312.87s tid=0x00007f45a05ee000 nid=0x293e waiting on condition  [0x00007f45d0abe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05ee000  [0x293e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"pool-1-thread-10" #22 prio=5 os_prio=0 cpu=1950.87ms elapsed=1312.87s tid=0x00007f45a05f0000 nid=0x293f waiting on condition  [0x00007f45d09bd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00007f45a05f0000  [0x293f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method)
	- parking to wait for  <0x0000000771123610> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@12-internal/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@12-internal/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@12-internal/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@12-internal/Thread.java:835)

"Attach Listener" #33 daemon prio=9 os_prio=0 cpu=0.28ms elapsed=0.59s tid=0x00007f45b4001000 nid=0x339d runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4001000  [0x339d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #34 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=0.59s tid=0x00007f45b4003000 nid=0x339e runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4003000  [0x339e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #35 daemon prio=9 os_prio=0 cpu=18.70ms elapsed=0.59s tid=0x00007f45b4005800 nid=0x339f runnable  [0x00007f452fbfb000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00007f45b4005800  [0x339f] State: _call_back _has_called_back 1 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at sun.util.locale.provider.LocaleServiceProviderPool.<clinit>(java.base@12-internal/LocaleServiceProviderPool.java:84)
	at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayNamesImpl(java.base@12-internal/TimeZoneNameUtility.java:178)
	at sun.util.locale.provider.TimeZoneNameUtility.retrieveDisplayName(java.base@12-internal/TimeZoneNameUtility.java:150)
	at java.util.TimeZone.getDisplayName(java.base@12-internal/TimeZone.java:401)
	at java.util.Date.toString(java.base@12-internal/Date.java:1046)
	at java.util.Properties.store0(java.base@12-internal/Properties.java:908)
	at java.util.Properties.store(java.base@12-internal/Properties.java:897)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:70)
	at jdk.internal.vm.VMSupport.serializePropertiesToByteArray(java.base@12-internal/VMSupport.java:75)

"VM Thread" os_prio=0 cpu=1297463.48ms elapsed=1317.03s tid=0x00007f45f4213000 nid=0x2910 runnable  

"GC Thread#0" os_prio=0 cpu=150.86ms elapsed=1318.05s tid=0x00007f45f4045800 nid=0x290c runnable  

"GC Thread#1" os_prio=0 cpu=55.77ms elapsed=1307.75s tid=0x00007f45c8003000 nid=0x294c runnable  

"GC Thread#2" os_prio=0 cpu=43.10ms elapsed=1307.75s tid=0x00007f45c8005000 nid=0x294d runnable  

"GC Thread#3" os_prio=0 cpu=54.89ms elapsed=1307.75s tid=0x00007f45c8006800 nid=0x294e runnable  

"GC Thread#4" os_prio=0 cpu=55.50ms elapsed=1307.75s tid=0x00007f45c8008800 nid=0x294f runnable  

"GC Thread#5" os_prio=0 cpu=52.90ms elapsed=1307.75s tid=0x00007f45c800a800 nid=0x2950 runnable  

"CMS Thread#0" os_prio=0 cpu=0.42ms elapsed=1317.26s tid=0x00007f45f40ad800 nid=0x290e runnable  

"CMS Thread#1" os_prio=0 cpu=0.36ms elapsed=1310.75s tid=0x00007f45c4001000 nid=0x294a runnable  
Comments
Fix request (11u) I would like to downport this for parity with 11.0.7-oracle. I had to resolve the test descriptoin because 14 specifies a timeout for the test.
08-12-2019

The test spends 95%(!) of its runtime in ClassLoaderData::free_deallocate_list in some verification routine I think (this is a fastdebug build) Perf trace (mangled, but readable): - 95.33% _ZN8VMThread4loopEv - 95.31% _ZN20SafepointSynchronize5beginEv _ZN20SafepointSynchronize16do_cleanup_tasksEv _ZN20ClassLoaderDataGraph34walk_metadata_and_clean_metaspacesEv _ZN20ClassLoaderDataGraph22clean_deallocate_listsEb - _ZN15ClassLoaderData20free_deallocate_listEv - 95.31% _ZN15ClassLoaderData20free_deallocate_listEv - 91.08% _ZN13InstanceKlass19deallocate_contentsEP15ClassLoaderData - 84.24% _ZN13InstanceKlass18deallocate_methodsEP15ClassLoaderDataP5ArrayIP6MethodE - _ZN13InstanceKlass18deallocate_methodsEP15ClassLoaderDataP5ArrayIP6MethodE - 84.22% _ZN20ClassLoaderMetaspace10deallocateEP8MetaWordmb - _ZN9metaspace12SpaceManager10deallocateEP8MetaWordm - _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - 84.21% _ZN20BinaryTreeDictionaryIN9metaspace9MetablockE8FreeListIS1_EE20insert_chunk_in_treeEPS1_ - _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E 84.19% _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E - 6.22% _ZN20ClassLoaderMetaspace10deallocateEP8MetaWordmb - _ZN9metaspace12SpaceManager10deallocateEP8MetaWordm - _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - 6.22% _ZN20BinaryTreeDictionaryIN9metaspace9MetablockE8FreeListIS1_EE20insert_chunk_in_treeEPS1_ - _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E - 0.58% _ZN15ClassLoaderData13remove_handleE9OopHandle 0.58% _ZN15ClassLoaderData13remove_handleE9OopHandle - 4.22% _ZN20ClassLoaderMetaspace10deallocateEP8MetaWordmb - _ZN9metaspace12SpaceManager10deallocateEP8MetaWordm _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - _ZN9metaspace13BlockFreelist12return_blockEP8MetaWordm - _ZN20BinaryTreeDictionaryIN9metaspace9MetablockE8FreeListIS1_EE20insert_chunk_in_treeEPS1_ - _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E _ZN8TreeListIN9metaspace9MetablockE8FreeListIS1_EE20return_chunk_at_tailEP9TreeChunkIS1_S3_E Ultimately I think the problem is the loop in FreeList<Chunk>::verify_chunk_in_free_list(), because nop'ing that one out improves the test significantly (it does not "hang" at the first unloading phase any more and within the 30s actually manages a few concurrent cycles), but I do not know how important this check is for integrity purposes (I do not think it is that useful to verify *all* chunks every time you delete a single one by default). The specific problem with CMS seems to be related to precleaning - this takes very long time (~5s until it is aborted) in this case, so its concurrent cycle takes very long, as the test accumulates more and more classloader data to unload. Since the algorithm with verification is O(n^2) at least, and n is much larger than with other cases with CMS, the test takes a very long time. There seems to be another long verification phase at the end of the run that seems independent of gc.
27-11-2018

Running the test with 30s stress time (as in the jtreg test) without jtreg: CMS with -XX:-CMSPrecleaningEnabled (no patch) takes 1:30min to complete. CMS with -XX:+CMSPrecleaningEnabled (default value, no patch) takes 7:30min to complete The mentioned long pause (probably caused by more verification) after the test has completed takes 1min (times above include this) So one short-term hack could be disabling CMS precleaning. It does not fix the 1min delay at the end of the test which is also wasted time (imo).
26-11-2018

[~lkorinth] - I removed 'maintainer-pain' because this failure is no longer frequently happening in the CI.
13-11-2018

So I did three runs on my Ubuntu machine that is also doing other testing (simulating parallel test load): $ taskset -c 1-6 make run-test-only CONF=linux-x86_64-normal-server-fastdebug TEST=vmTestbase/metaspace/stressDictionary/StressDictionary.java JTREG='VM_OPTIONS=-XX:MaxRAMPercentage=25 -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled' Here are the times for the test execution section: elapsed time (seconds): 343.859 elapsed time (seconds): 244.485 elapsed time (seconds): 256.158 Average is 281.50. And then I did three more runs with one more option: $ taskset -c 1-6 make run-test-only CONF=linux-x86_64-normal-server-fastdebug TEST=vmTestbase/metaspace/stressDictionary/StressDictionary.java JTREG='VM_OPTIONS=-XX:MaxRAMPercentage=25 -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:-ZapUnusedHeapArea' Here are the times for the test execution section: elapsed time (seconds): 161.198 elapsed time (seconds): 340.13 elapsed time (seconds): 269.209 Average is 256.84. So with -XX:-ZapUnusedHeapArea, the average is < 30 seconds better.
02-11-2018

Here's a snippet from the log for the jdk12-jdk-733-tier3 CI job set failure: #section:main ----------messages:(6/310)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm/timeout=300 metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 1424.55 ----------configuration:(0/0)---------- ----------System.out:(1124/83005)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 7860256768 Sleep time: 500 Iterations: 0 Number of threads: 12 Seed: 1540944559294 Run GC thread: false Run mem diag thread: false Run forever: false Timeout refired 1200 times <snip> ----------System.err:(5/247)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. INFO: There are 20 results. INFO: no tasks were cancelled. INFO: all tasks are done. STATUS:Passed. So the test timed out at 20 minutes and while JTREG was gathering information about the hang, the test finished. Update: Here's the "test analysis" info for this test in jdk12-jdk-733-tier3: Test run details for vmTestbase/metaspace/stressDictionary/StressDictionary.java Tier Platform Task Test Options tier3 linux-x64-debug 23m 45s -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 3m 50s -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseNUMA -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 52s -XX:+UseSerialGC -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 35s -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:+IgnoreUnrecognizedVMOptions Our execution range is 35 seconds to 23 minutes 45 seconds.
02-11-2018

Here's the "test analysis" info for the test in the CI job set that contains the fix for JDK-8212220: Test run details for vmTestbase/metaspace/stressDictionary/StressDictionary.java Tier Platform Task Test Options tier3 linux-x64-debug 4m 42s -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 1m 39s -XX:+UseSerialGC -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 41s -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseNUMA -XX:+IgnoreUnrecognizedVMOptions tier3 linux-x64-debug 40s -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:+IgnoreUnrecognizedVMOptions We have quite the range of durations.
24-10-2018

Disabling "zap" results in 330 seconds with CMS without MaxRAMPercent=25.
24-10-2018

[~dholmes] Try running with -XX:-ZapUnusedHeapArea. When G1 is not selected, I noticed that some GCs spend a TON of time filling the heap at start-up, which is very bad when running on a machine with large RAM size. This could be a regression in recent JDKs, as I don't remember having that problem during JDK8 time, for example.
24-10-2018

Not sure how I observed the 10x for G1 versus CMS originally. Re-running now shows 30 seconds for G1 and 82 for CMS. The MaxRAMPercent=25 had no affect on the G1 results on my machine. But for CMS the test runs much slower (215 seconds) without MaxRAMPercent set. I think we need to raise a bug with jtreg to get some kind of flag set as soon as the timeout Alarm fires, such that the checking of the returning code can notice that the timeout also fired. There would still be a race but it would be very small now and wouldn't allow a timed-out test to report success if we spend a few minutes grabbing stack dumps in the timeout handler.
24-10-2018

Another experiment adding one more option: $ taskset -c 1-6 do_java_test -V '-XX:MaxRAMPercentage=25 -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled' vmTestbase/metaspace/stressDictionary/StressDictionary.java 2>&1 | tee do_java_test.log INFO: GNUMAKE=make INFO: GNUMAKE version is: INFO: GNU Make 4.1 INFO: Built for x86_64-pc-linux-gnu INFO: Copyright (C) 1988-2014 Free Software Foundation, Inc. INFO: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> INFO: This is free software: you are free to change and redistribute it. INFO: There is NO WARRANTY, to the extent permitted by law. INFO: JTREG options: INFO: JOBS=16 INFO: TEST_MODE=othervm INFO: VM_OPTIONS=-XX:MaxRAMPercentage=25 -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled INFO: test_val=vmTestbase/metaspace/stressDictionary/StressDictionary.java Test Config: linux-x86_64-normal-server-release INFO: TIMEOUT=4 Done testing Test Run linux-x86_64-normal-server-release time: 0.99 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Test Config: linux-x86_64-normal-server-fastdebug INFO: TIMEOUT=6 Done testing Test Run linux-x86_64-normal-server-fastdebug time: 5.89 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Test Config: linux-x86_64-normal-server-slowdebug INFO: TIMEOUT=12 Done testing Test Run linux-x86_64-normal-server-slowdebug time: 2.89 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Total test time: 9.77 minutes. $ grep '^elapsed time' results.CMS_MaxRAM_options/StressDictionary.jtr.fastdebug elapsed time (seconds): 7.003 elapsed time (seconds): 6.999 elapsed time (seconds): 0.471 elapsed time (seconds): 9.029 elapsed time (seconds): 9.028 elapsed time (seconds): 276.888 So adding the -XX:MaxRAMPercentage=25 option changed the time from: > elapsed time (seconds): 74.266 to: > elapsed time (seconds): 276.888 So that's much closer to the 10x that David reported! Update: One thing that's curious is that the addition of the '-XX:MaxRAMPercentage=25' option only seems to have affected the fast debug config: > Test Run linux-x86_64-normal-server-release time: 0.99 minutes. > Test Run linux-x86_64-normal-server-fastdebug time: 5.89 minutes. > Test Run linux-x86_64-normal-server-slowdebug time: 2.89 minutes. compared to the previous run: > Test Run linux-x86_64-normal-server-release time: 0.81 minutes. > Test Run linux-x86_64-normal-server-fastdebug time: 2.15 minutes. > Test Run linux-x86_64-normal-server-slowdebug time: 2.20 minutes.
23-10-2018

Another experiment with trying to reproduce the failure mode on my Ubuntu machine. Had to make the following change to the test so that the new "INFO" lines show up in System.err instead of getting lost in System.out's output overflow from the thread dumps: $ diff 8211211.diff.debug.txt.01 8211211.diff.debug.txt.03 20c20 < + System.out.println("INFO: There are " + act_results + " results."); --- > + System.err.println("INFO: There are " + act_results + " results."); 41c41 < + System.out.println("INFO: no tasks were cancelled."); --- > + System.err.println("INFO: no tasks were cancelled."); 44c44 < + System.out.println("INFO: all tasks are done."); --- > + System.err.println("INFO: all tasks are done."); Running the test with minimal infrastructure like this: $ taskset -c 1-6 make run-test-only CONF=linux-x86_64-normal-server-fastdebug TEST=vmTestbase/metaspace/stressDictionary/StressDictionary.java JTREG='TIMEOUT=0.5; VM_OPTIONS=-XX:MaxRAMPercentage=25 -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled' sets the test's total timeout to 60 seconds and has these interesting snippets in the output: ACTION: main -- Error. Program `/work/shared/bug_hunt/jdk_jdk_exp/build/linux-x86_64-normal-server-fastdebug/images/jdk/bin/java' timed out (timeout set to 60000ms, elapsed time including timeout handling was 268827ms). REASON: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 TIME: 268.836 seconds messages: command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 268.836 configuration: STDOUT: Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 16819290112 Sleep time: 500 Iterations: 0 Number of threads: 12 Seed: 1540319620206 Run GC thread: false Run mem diag thread: false Run forever: false Timeout refired 60 times 2018-10-23 14:37:45 <snip> STDERR: Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. INFO: There are 20 results. INFO: no tasks were cancelled. INFO: all tasks are done. STATUS:Passed. So the test times out as expected and JTREG did at least three thread dumps: Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-2018-10-15-160 7309.dcubed.jdkjdkexp mixed mode, sharing): Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-2018-10-15-160 7309.dcubed.jdkjdkexp mixed mode, sharing): Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-2018-10-15-160 7309.dcubed.jdkjdkexp mixed mode, sharing): and while that was all happening, the test managed to finish and we see this in System.err: INFO: There are 20 results. INFO: no tasks were cancelled. INFO: all tasks are done. STATUS:Passed. I think this confirms David's theory: > The longer the handler takes to execute the more likely > the process may terminate "normally".
23-10-2018

[~dholmes] - Interesting. I also did a taskset experiment last night... $ taskset -pc 1-6 $$ pid 26800's current affinity list: 0-31 pid 26800's new affinity list: 1-6 $ do_java_test -V '-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled' vmTestbase/metaspace/stressDictionary/StressDictionary.java 2>&1 | tee do_java_test.log INFO: GNUMAKE=make INFO: GNUMAKE version is: INFO: GNU Make 4.1 INFO: Built for x86_64-pc-linux-gnu INFO: Copyright (C) 1988-2014 Free Software Foundation, Inc. INFO: License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> INFO: This is free software: you are free to change and redistribute it. INFO: There is NO WARRANTY, to the extent permitted by law. INFO: JTREG options: INFO: JOBS=16 INFO: TEST_MODE=othervm INFO: VM_OPTIONS=-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled INFO: test_val=vmTestbase/metaspace/stressDictionary/StressDictionary.java Test Config: linux-x86_64-normal-server-release INFO: TIMEOUT=4 Done testing Test Run linux-x86_64-normal-server-release time: 0.81 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Test Config: linux-x86_64-normal-server-fastdebug INFO: TIMEOUT=6 Done testing Test Run linux-x86_64-normal-server-fastdebug time: 2.15 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Test Config: linux-x86_64-normal-server-slowdebug INFO: TIMEOUT=12 Done testing Test Run linux-x86_64-normal-server-slowdebug time: 2.20 minutes. jtreg:open/test/hotspot/jtreg/vmTestbase/metaspace/stressDictionary/StressDictionary.java 1 1 0 0 Total test time: 5.15 minutes. $ grep '^elapsed time' build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_metaspace_stressDictionary_StressDictionary_java/vmTestbase/metaspace/stressDictionary/StressDictionary.jtr elapsed time (seconds): 2.452 elapsed time (seconds): 2.449 elapsed time (seconds): 0.572 elapsed time (seconds): 3.77 elapsed time (seconds): 3.769 elapsed time (seconds): 74.266 So with 6 procs, the test with the CMS options went from: > elapsed time (seconds): 48.528 to: > elapsed time (seconds): 74.266 For comparison, the G1 time is: > elapsed time (seconds): 30.707 So while I'm also seeing a slow down with CMS options, I'm not able to confirm this: > The test takes 10x longer to run with CMS than it does for G1.
23-10-2018

This test has an interesting execution profile based on the number of processors available to it. On a linux box with 24 procs it runs in around 64 seconds. Yet I also see the following when run under taskset: 1 proc: 107 seconds 4 proc: 240 seconds 6 proc: 277 seconds 8 proc: 254 seconds 12 proc: 90 seconds 16 proc: 97 seconds 20 proc: 67 seconds
23-10-2018

AFAICS jtreg timeout handling is asynchronous and thus racy. A timeout handler is registered with an "alarm" and we then have: errCopier.join(); int exitCode = process.waitFor(); // if the timeout hasn't fired, cancel it as quickly as possible alarm.cancel(); return getStatus(exitCode, statusScanner.exitStatus()); So the process may complete successfully around the same time that the timeout would fire and we're too late in cancelling the alarm and we return the success code but the timeout handler will still execute. Further it seems to me that once the timeout handler is released there is a race between the process exiting normally and the handler eventually "destroying" the process which would result in a non-success error code. The longer the handler takes to execute the more likely the process may terminate "normally".
23-10-2018

Running the test on my Ubuntu 16.04 machine without any options: $ grep '^elapsed time' results.no_vm_options/StressDictionary.jtr.fastdebug elapsed time (seconds): 3.188 elapsed time (seconds): 3.18 elapsed time (seconds): 0.582 elapsed time (seconds): 4.64 elapsed time (seconds): 4.639 elapsed time (seconds): 30.707 Running the test on my Ubuntu 16.04 machine with these CMS options -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled: $ grep '^elapsed time' results.CMS_options/StressDictionary.jtr.fastdebug elapsed time (seconds): 3.092 elapsed time (seconds): 3.088 elapsed time (seconds): 0.565 elapsed time (seconds): 4.535 elapsed time (seconds): 4.534 elapsed time (seconds): 48.528 My Ubuntu machine is a T7600 with 64GB of RAM and 2 - Intel(R) Xeon(R) CPU E5-2665 0 @ 2.40GHz, each with 8 cores, and 16 threads. Update: I looked at the 6 most recent sightings of this test failure in the jdk/jdk CI and all of those failures happened on machines with 6 or 8 cores. I'm also wondering if we're not getting the thread dumps on the 6 core machines, but we are on the 8 core machines, but I don't know. Update: I have thread dumps on 8 core machines and no threads dumps on 8 core machines so number of cores isn't an issue for the thread dumps.
23-10-2018

With the failure in the jdk12-jdk-649-tier3 CI job set, the timeout has changed from 20+ minutes to 11-12 minutes with this sighting. The fix for JDK-8212028 was pushed on 2018.10.15 and that change removed the Mach5 TIMEOUT_FACTOR override setting of 10. So now we are picking up a different TIMEOUT_FACTOR from somewhere else. Here's a snippet from the log for the jdk12-jdk-649-tier3 failure: ----------System.out:(13/287)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 7860256768 Sleep time: 500 Iterations: 0 Number of threads: 12 Seed: 1539647196530 Run GC thread: false Run mem diag thread: false Run forever: false Timeout refired 480 times ----------System.err:(1/147)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. ----------rerun:(29/7258)*---------- <snip> result: Error. Program `/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.649/linux-x64-debug.jdk/jdk-12/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 719658ms). test result: Error. Program `/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.649/linux-x64-debug.jdk/jdk-12/fastdebug/bin/java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 719658ms). so the TIMEOUT_FACTOR must now be 4 (120 second default timeout X 4 == 480 seconds). So we've gone from a timeout value of 20 minutes down to 8 minutes (per run cmd). That explains why we're seeing more frequent sighting of this test failing. Update: Since 2018.10.15, we're seeing a mix of failures with "STATUS:Passed." in the System.err section along with a Thread dump in the System.out section along with this latest failure mode where we don't have a Thread dump and we don't have a "STATUS:Passed." in the System.err section. Very strange since they are all still time outs.
22-10-2018

It's possible there is a race in the timeout cases such that the test can be finishing around the same time that the framework decides it should timeout and interrupts it. In that case the test main() completes normally in the MainThread, the join() returns and the main thread proceeds to execute: Astatus.passed("").exit) which is what we see in the thread dump for the main thread in the "passed but timedout case". That dump also doesn't show the MainThread as it has completed. In other dumps the test case has not completed and so we see main, MainThread and all the pool workers.
16-10-2018

AFAICS the timeout only happens when using CMS: :-XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled The test takes 10x longer to run with CMS than it does for G1.
16-10-2018

Mach5 is only showing this failure on Linux-X64 (so far).
16-10-2018

I think jtreg uses the "main" thread to start a new thread that executes the test main() - the MainThread - and then join()s it. So you expect to see the main thread blocked in join() because this thread is still executing: "MainThread" #12 prio=5 os_prio=0 cpu=3162.82ms elapsed=1315.70s tid=0x00007f45f4440800 nid=0x291a waiting on condition [0x00007f45d1cc7000] java.lang.Thread.State: WAITING (parking) JavaThread state: _thread_blocked Thread: 0x00007f45f4440800 [0x291a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method) - parking to wait for <0x00000007711efae0> (a java.util.concurrent.FutureTask) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.FutureTask.awaitDone(java.base@12-internal/FutureTask.java:447) and as you note the pool threads are still working hence MainThread is also blocked.
16-10-2018

The original test started at this time: start=Thu Sep 27 00\:39\:43 PDT 2018 and ended at this time: end=Thu Sep 27 01\:02\:04 PDT 2018 The first thread dump occurred at this time: 2018-09-27 01:01:57 Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.520 mixed mode): and that thread dump shows that test's main() is done and has returned to the JTREG main wrapper: "main" #1 prio=5 os_prio=0 cpu=1064.84ms elapsed=1317.51s tid=0x00007f45f401d800 nid=0x290b in Object.wait() [0x00007f45fc444000] java.lang.Thread.State: WAITING (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45f401d800 [0x290b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@12-internal/Native Method) - waiting on <0x0000000770f89580> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1308) - waiting to re-lock in wait() <0x0000000770f89580> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1375) at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74) However, other threads are listed in this thread dump and they appear to be executing test code. See uses of metaspace.stressDictionary.StressDictionary code below: "MainThread" #12 prio=5 os_prio=0 cpu=3162.82ms elapsed=1315.70s tid=0x00007f45f4440800 nid=0x291a waiting on condition [0x00007f45d1cc7000] java.lang.Thread.State: WAITING (parking) JavaThread state: _thread_blocked Thread: 0x00007f45f4440800 [0x291a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method) - parking to wait for <0x00000007711efae0> (a java.util.concurrent.FutureTask) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.FutureTask.awaitDone(java.base@12-internal/FutureTask.java:447) at java.util.concurrent.FutureTask.get(java.base@12-internal/FutureTask.java:190) at java.util.concurrent.AbstractExecutorService.invokeAll(java.base@12-internal/AbstractExecutorService.java:247) at metaspace.stressDictionary.StressDictionary.run(StressDictionary.java:127) at nsk.share.test.Tests$TestRunner.execute(Tests.java:82) at nsk.share.test.Tests$TestRunner.run(Tests.java:96) at nsk.share.test.Tests.runTest(Tests.java:102) at metaspace.stressDictionary.StressDictionary.main(StressDictionary.java:109) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@12-internal/Native Method) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@12-internal/NativeMethodAccessorImpl.java:62) at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@12-internal/DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(java.base@12-internal/Method.java:566) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-1" #13 prio=5 os_prio=0 cpu=1480.38ms elapsed=1312.33s tid=0x00007f45a05dc800 nid=0x2936 waiting for monitor entry [0x00007f45d12c6000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05dc800 [0x2936] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-2" #14 prio=5 os_prio=0 cpu=1454.51ms elapsed=1312.33s tid=0x00007f45a05de800 nid=0x2937 waiting for monitor entry [0x00007f45d11c5000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05de800 [0x2937] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-3" #15 prio=5 os_prio=0 cpu=1887.80ms elapsed=1312.33s tid=0x00007f45a05e0800 nid=0x2938 waiting for monitor entry [0x00007f45d10c4000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05e0800 [0x2938] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-5" #17 prio=5 os_prio=0 cpu=1752.92ms elapsed=1312.33s tid=0x00007f45a05e5000 nid=0x293a runnable [0x00007f45d0ec2000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00007f45a05e5000 [0x293a] State: _call_back _has_called_back 1 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-6" #18 prio=5 os_prio=0 cpu=1796.16ms elapsed=1312.33s tid=0x00007f45a05e7000 nid=0x293b waiting for monitor entry [0x00007f45d0dc1000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05e7000 [0x293b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-7" #19 prio=5 os_prio=0 cpu=1481.51ms elapsed=1312.32s tid=0x00007f45a05e9800 nid=0x293c waiting for monitor entry [0x00007f45d0cc0000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05e9800 [0x293c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-8" #20 prio=5 os_prio=0 cpu=1937.67ms elapsed=1312.32s tid=0x00007f45a05eb800 nid=0x293d waiting for monitor entry [0x00007f45d0bbf000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05eb800 [0x293d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-9" #21 prio=5 os_prio=0 cpu=1527.32ms elapsed=1312.32s tid=0x00007f45a05ee000 nid=0x293e waiting for monitor entry [0x00007f45d0abe000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05ee000 [0x293e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-1-thread-10" #22 prio=5 os_prio=0 cpu=1907.46ms elapsed=1312.32s tid=0x00007f45a05f0000 nid=0x293f waiting for monitor entry [0x00007f45d09bd000] java.lang.Thread.State: BLOCKED (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45a05f0000 [0x293f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ClassLoader.defineClass1(java.base@12-internal/Native Method) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:1016) at java.lang.ClassLoader.defineClass(java.base@12-internal/ClassLoader.java:877) at metaspace.stressDictionary.ClassloaderUnderTest.define(ClassloaderUnderTest.java:35) at metaspace.stressDictionary.StressDictionary$FillingDictionaryWorker.call(StressDictionary.java:69) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@12-internal/ThreadPoolExecutor.java:1128) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@12-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) Not that not every pool thread is executing metaspace.stressDictionary.StressDictionary but a bunch of them are. Now I'm starting to wonder how main() managed to return from: ExecutorService executorService = Executors.newCachedThreadPool(); try { executorService.invokeAll(tasks); } catch (InterruptedException e) { e.printStackTrace(); } with threads in the pool still doing work...
15-10-2018

Here's the "main" thread from the first thread dump in the file: "main" #1 prio=5 os_prio=0 cpu=1064.84ms elapsed=1317.51s tid=0x00007f45f401d800 nid=0x290b in Object.wait() [0x00007f45fc444000] java.lang.Thread.State: WAITING (on object monitor) JavaThread state: _thread_blocked Thread: 0x00007f45f401d800 [0x290b] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@12-internal/Native Method) - waiting on <0x0000000770f89580> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1308) - waiting to re-lock in wait() <0x0000000770f89580> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1375) at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74) Looks like in this test run, our test's main() has finished and now our main() thread is in: com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74) calling: java.lang.Thread.join(java.base@12-internal/Thread.java:1375) So for some reason, JTREG is hung.
15-10-2018

There four thread dumps in the log file that mention the main() thread. The last one looks like this: "main" #1 prio=5 os_prio=0 cpu=1077.75ms elapsed=1318.05s tid=0x00007f45f401d800 nid=0x290b runnable [0x00007f45fc444000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00007f45f401d800 [0x290b] State: _call_back _has_called_back 1 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Shutdown.halt0(java.base@12-internal/Native Method) at java.lang.Shutdown.halt(java.base@12-internal/Shutdown.java:152) - locked <0x000000076a1329f8> (a java.lang.Shutdown$Lock) at java.lang.Shutdown.exit(java.base@12-internal/Shutdown.java:175) - locked <0x000000076a132878> (a java.lang.Class for java.lang.Shutdown) at java.lang.Runtime.exit(java.base@12-internal/Runtime.java:115) at java.lang.System.exit(java.base@12-internal/System.java:1746) at com.sun.javatest.regtest.agent.AStatus.exit(AStatus.java:199) at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:84)
15-10-2018

Another thing to sanity check is the execution time of main() to see if it is prematurely returning and that's what causes JTREG to issue: "STATUS:Passed." public static void main(String[] args) { long start = System.currentTimeMillis(); System.out.println("XXX Start test @ " + start); StressDictionary.args = args; Tests.runTest(new StressDictionary(), args); long end = System.currentTimeMillis(); System.out.println("XXX End test @ " + end); System.out.println("XXX duration=" + (end - start) + "ms"); } Shows this for one of my runs: ----------System.out:(15/341)---------- XXX Start test @ 1539636933010 Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 675282944 Sleep time: 500 Iterations: 0 Number of threads: 20 Seed: 1539636933247 Run GC thread: false Run mem diag thread: false Run forever: false XXX End test @ 1539636963359 XXX duration=30349ms ----------System.err:(1/15)---------- so the test is indeed taking 30 seconds to run. Sigh...
15-10-2018

Added some debug code to RunParams.java and it shows: getMediumLoadThreadsCount() set numberOfThreads to 20 so it appears that the "Number of threads:" output line is not affected by the number of threads we create in our test. Just to prove that to myself, I changed the test: private static final int NUMBER_OF_CORRUPTING_THREADS = 9; private static final int NUMBER_OF_NOT_CORRUPTING_THREADS = 9; and we still get: Number of threads: 20
15-10-2018

open/test/hotspot/jtreg/vmTestbase/nsk/share/runner/RunParams.java public void printConfig(PrintStream out) { stressOptions.printInfo(out); out.println("Max memory: " + Runtime.getRuntime().maxMemory()); out.println("Sleep time: " + sleepTime); out.println("Iterations: " + iterations); out.println("Number of threads: " + numberOfThreads); out.println("Seed: " + seed); out.println("Run GC thread: " + runGCThread); out.println("Run mem diag thread: " + runMemDiagThread); out.println("Run forever: " + runForever); } public void logConfig(Log log) { log.debug("Max memory: " + Runtime.getRuntime().maxMemory()); log.debug("Sleep time: " + sleepTime); log.debug("Iterations: " + iterations); log.debug("Number of threads: " + numberOfThreads); log.debug("Seed: " + seed); log.debug("Run GC thread: " + runGCThread); log.debug("Run mem diag thread: " + runMemDiagThread); log.debug("Run forever: " + runForever); }
15-10-2018

Just noticed something else... All of my passing runs have this line: Number of threads: 20 and the four sightings in Mach5 have these lines: Number of threads: 12 Number of threads: 12 Number of threads: 16 Number of threads: 12 Taking a look at the test: private static final int NUMBER_OF_CORRUPTING_THREADS = 10; private static final int NUMBER_OF_NOT_CORRUPTING_THREADS = 10; List<Callable<Object>> tasks = new LinkedList<Callable<Object>>(); for (int i = 0; i < NUMBER_OF_CORRUPTING_THREADS; i++) { tasks.add(this.new FillingDictionaryWorker()); } for (int i = 0; i < NUMBER_OF_NOT_CORRUPTING_THREADS; i++) { tasks.add(this.new RegularWorker()); } ExecutorService executorService = Executors.newCachedThreadPool(); try { executorService.invokeAll(tasks); } catch (InterruptedException e) { e.printStackTrace(); } I would expect the test to always have NUMBER_OF_CORRUPTING_THREADS + NUMBER_OF_NOT_CORRUPTING_THREADS or 20 threads. Gonna have to chase down where the "Number of threads" output is generated and what all it is used for...
15-10-2018

Ran the test on my Ubuntu test machine with a freshly built jdk/jdk repo: fastdebug bits: #section:main ----------messages:(4/247)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] elapsed time (seconds): 30.558 ----------configuration:(0/0)---------- ----------System.out:(12/260)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 675282944 Sleep time: 500 Iterations: 0 Number of threads: 20 Seed: 1539627341067 Run GC thread: false Run mem diag thread: false Run forever: false ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(25/4283)*---------- release bits: #section:main ----------messages:(4/247)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] elapsed time (seconds): 30.376 ----------configuration:(0/0)---------- ----------System.out:(12/260)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 675282944 Sleep time: 500 Iterations: 0 Number of threads: 20 Seed: 1539627247470 Run GC thread: false Run mem diag thread: false Run forever: false ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(25/4253)*---------- slowdebug bits: #section:main ----------messages:(4/247)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] elapsed time (seconds): 30.846 ----------configuration:(0/0)---------- ----------System.out:(12/260)---------- Stress time: 30 seconds Stress iterations factor: 1 Stress threads factor: 1 Stress runs factor: 1 Max memory: 675282944 Sleep time: 500 Iterations: 0 Number of threads: 20 Seed: 1539627423087 Run GC thread: false Run mem diag thread: false Run forever: false ----------System.err:(1/15)---------- STATUS:Passed. ----------rerun:(25/4284)*----------
15-10-2018

Looking at the four sightings linked in Mach5: mach5-one-jdk12-jdk-520-tier3-20180927-0732-3065-tier3-gc-jdk_open_test_hotspot_jtreg_vmTestbase_vm_metaspace-any-debug-158-13/log #section:main ----------messages:(6/299)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 1325.169 ----------configuration:(0/0)---------- <snip> ----------System.err:(2/162)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. STATUS:Passed. ----------rerun:(31/6676)*---------- mach5-one-jdk12-jdk-527-tier3-20180927-2303-3259-tier3-gc-jdk_open_test_hotspot_jtreg_vmTestbase_vm_metaspace-any-debug-158-13/log #section:main ----------messages:(6/299)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 1279.339 ----------configuration:(0/0)---------- <snip> ----------System.err:(2/162)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. STATUS:Passed. ----------rerun:(31/6676)*---------- mach5-one-jdk12-jdk-570-tier3-20181004-1612-4525-tier3-gc-vmTestbase_vm_metaspace-any-debug-158-13/log #section:main ----------messages:(6/299)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 1340.954 ----------configuration:(0/0)---------- <snip> ----------System.err:(2/162)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. STATUS:Passed. ----------rerun:(31/6711)*---------- mach5-one-jdk12-jdk-571-tier3-20181004-1728-4539-tier3-gc-vmTestbase_vm_metaspace-any-debug-158-13/log #section:main ----------messages:(6/299)---------- command: main metaspace.stressDictionary.StressDictionary -stressTime 30 reason: User specified action: run main/othervm metaspace.stressDictionary.StressDictionary -stressTime 30 Mode: othervm [/othervm specified] Timeout information: --- Timeout information end. elapsed time (seconds): 1280.209 ----------configuration:(0/0)---------- <snip> ----------System.err:(2/162)---------- Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. STATUS:Passed. ----------rerun:(31/6700)*---------- The test that hangs is run in "/othervm" mode and all of the System.err sections report "STATUS:Passed.". So JTREG thinks this test has passed, but each of these tests timed out at 20+ minutes. That seems a bit odd for a test using "-stressTime 30" to restrict run time to 30 seconds.
15-10-2018