JDK-8176214 : compiler/compilercontrol/jcmd/StressAddMultiThreadedTest.java frequently times out
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 9,10,11,12,13,14
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2017-03-06
  • Updated: 2024-01-31
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.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8217170 - gc/arguments/TestUseCompressedOopsErgo.java timed out
Sub Tasks
JDK-8218195 :  
Diagnostic output for test library ProcessTools - Closed
JDK-8218582 :  
Improve diagnostic of c/cc/jcmd/StressAddMultiThreadedTest.java - Open
Description
Sometimes compiler/compilercontrol/jcmd/StressAddMultiThreadedTest.java is killed by timeout. There is no evidence of vm failure.
Comments
Spotted in jdk-13-1089: https://java.se.oracle.com:10065/mdash/jobs/mach5-one-jdk-13-1089-tier3-20190521-1707-2608180/results?search=status%3Afailed+AND+-state%3Ainvalid
21-05-2019
or it might have been processing the received jcmd commands.
12-02-2019
In a recent failure, hotspot_pid20307.log contains this for one of the compiler threads: <phase name='codeinstall' stamp='0.757'> <phase_done name='codeinstall' stamp='0.758'/> </phase> <code_cache total_blobs='1242' nmethods='254' adapters='832' free_code_cache='249049216'/> <task_done success='1' nmsize='312' count='128' stamp='0.758'/> </task> <task compile_id='255' method='java.util.HashMap$KeyIterator next ()Ljava/lang/Object;' bytes='8' count='1042' iicount='1042' level='3' stamp='1237.196'> <phase name='setup' stamp='1237.200'> <phase_done name='setup' stamp='1237.200'/> </phase> The timestamp jumps from < 1 to > 1200, as if it got stuck and then later unstuck. Or maybe the JVM was just idle with no compiles to do, for 1200 seconds?
12-02-2019
The exit code 134 is 128 + signal # 6 = SIGABRT.
06-02-2019
it's kinda hard to tell where whose stdout/stderr/exit code are, b/c the test just prints them into its default output streams. and jtreg/jt-harness doesn't make it easier by removing middle of the output. I'll try to improve the test so it will dump output and error streams and exit code to files.
06-02-2019
.jtr file also has the following lines: ``` Command returned with exit code 134 ---------------- stdout ---------------- 10100: ---------------- stderr ---------------- ---------------------------------------- Not enough time to continue execution. Interrupted. ``` as far as I can tell 134 is an exit code from one of jcmd process.
06-02-2019
after JDK-8218197, diagnostic information gathered by timeout-handler looks more sane. there are 3 processes: 1. 6493 -- main test process 2. 10167 -- jcmd 3. 10100 -- jvm which jcmd connects to 6493 and 10167 are alive when timeout-handler starts to work on them, 10100 is dead stack traces: ---------------------------------------- [2019-02-06 07:17:13] [/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk13-jdk.327/linux-x64-debug.jdk/jdk-13/fastdebug/bin/jstack, 6493] timeout=20000 ---------------------------------------- 2019-02-06 07:17:13 Full thread dump Java HotSpot(TM) 64-Bit Server VM (13-internal+0-jdk13-jdk.327 mixed mode): Threads class SMR info: _java_thread_list=0x00007f3430002230, length=13, elements={ 0x00007f348401d800, 0x00007f348449f800, 0x00007f34844a5000, 0x00007f34844f0000, 0x00007f34844f3000, 0x00007f34844f5800, 0x00007f3484507000, 0x00007f34845b4800, 0x00007f348474a800, 0x00007f348486a000, 0x00007f3410208000, 0x00007f3408012000, 0x00007f3430001000 } _java_thread_list_alloc_cnt=228, _java_thread_list_free_cnt=226, _java_thread_list_max=38, _nested_thread_list_max=1 _tlh_cnt=11043, _tlh_times=18, avg_tlh_time=0.00, _tlh_time_max=8 _deleted_thread_cnt=107, _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=0, _to_delete_list_max=2 "main" #1 prio=5 os_prio=0 cpu=1222.11ms elapsed=740.33s tid=0x00007f348401d800 nid=0x195e runnable [0x00007f348f1c3000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f348401d800 [0x195e] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.net.SocketInputStream.socketRead0(java.base@13-internal/Native Method) at java.net.SocketInputStream.socketRead(java.base@13-internal/SocketInputStream.java:115) at java.net.SocketInputStream.read(java.base@13-internal/SocketInputStream.java:168) at java.net.SocketInputStream.read(java.base@13-internal/SocketInputStream.java:140) at java.io.BufferedInputStream.fill(java.base@13-internal/BufferedInputStream.java:252) at java.io.BufferedInputStream.read(java.base@13-internal/BufferedInputStream.java:271) - locked <0x00000005e8736760> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(java.base@13-internal/FilterInputStream.java:83) at com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:187) at com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:65) "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=2.54ms elapsed=740.12s tid=0x00007f348449f800 nid=0x1967 waiting on condition [0x00007f345c2ff000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f348449f800 [0x1967] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ref.Reference.waitForReferencePendingList(java.base@13-internal/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@13-internal/Reference.java:241) at java.lang.ref.Reference$ReferenceHandler.run(java.base@13-internal/Reference.java:213) "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.39ms elapsed=740.12s tid=0x00007f34844a5000 nid=0x1968 in Object.wait() [0x00007f345c1fe000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f34844a5000 [0x1968] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@13-internal/Native Method) - waiting on <0x00000005e86c6db0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:155) - locked <0x00000005e86c6db0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:176) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@13-internal/Finalizer.java:170) "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.64ms elapsed=740.07s tid=0x00007f34844f0000 nid=0x1969 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f34844f0000 [0x1969] 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=2755.98ms elapsed=740.07s tid=0x00007f34844f3000 nid=0x196a waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f34844f3000 [0x196a] 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=3800.86ms elapsed=740.05s tid=0x00007f34844f5800 nid=0x196b waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f34844f5800 [0x196b] 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=47.03ms elapsed=740.02s tid=0x00007f3484507000 nid=0x196c runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f3484507000 [0x196c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "Common-Cleaner" #9 daemon prio=8 os_prio=0 cpu=5.11ms elapsed=739.86s tid=0x00007f34845b4800 nid=0x196d in Object.wait() [0x00007f344dbfa000] java.lang.Thread.State: TIMED_WAITING (on object monitor) Thread: 0x00007f34845b4800 [0x196d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@13-internal/Native Method) - waiting on <0x00000005e864a5b0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:155) - locked <0x00000005e864a5b0> (a java.lang.ref.ReferenceQueue$Lock) at jdk.internal.ref.CleanerImpl.run(java.base@13-internal/CleanerImpl.java:148) at java.lang.Thread.run(java.base@13-internal/Thread.java:835) at jdk.internal.misc.InnocuousThread.run(java.base@13-internal/InnocuousThread.java:134) "Service Thread" #10 daemon prio=9 os_prio=0 cpu=6.37ms elapsed=739.60s tid=0x00007f348474a800 nid=0x196f runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f348474a800 [0x196f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "pool-1-thread-1" #11 daemon prio=5 os_prio=0 cpu=23.64ms elapsed=739.31s tid=0x00007f348486a000 nid=0x1981 waiting on condition [0x00007f344d6d1000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f348486a000 [0x1981] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@13-internal/Native Method) - parking to wait for <0x00000005e86b4f98> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@13-internal/LockSupport.java:235) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@13-internal/AbstractQueuedSynchronizer.java:2123) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@13-internal/ScheduledThreadPoolExecutor.java:1182) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@13-internal/ScheduledThreadPoolExecutor.java:899) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@13-internal/ThreadPoolExecutor.java:1054) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@13-internal/ThreadPoolExecutor.java:1114) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@13-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@13-internal/Thread.java:835) "process reaper" #33 daemon prio=10 os_prio=0 cpu=6.58ms elapsed=575.31s tid=0x00007f3410208000 nid=0x24c5 waiting on condition [0x00007f345c097000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f3410208000 [0x24c5] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@13-internal/Native Method) - parking to wait for <0x00000005e8813020> (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@13-internal/LockSupport.java:235) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@13-internal/SynchronousQueue.java:462) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@13-internal/SynchronousQueue.java:361) at java.util.concurrent.SynchronousQueue.poll(java.base@13-internal/SynchronousQueue.java:937) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@13-internal/ThreadPoolExecutor.java:1053) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@13-internal/ThreadPoolExecutor.java:1114) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@13-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@13-internal/Thread.java:835) "process reaper" #56 daemon prio=10 os_prio=0 cpu=1.24ms elapsed=543.98s tid=0x00007f3408012000 nid=0x2622 waiting on condition [0x00007f345c073000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f3408012000 [0x2622] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@13-internal/Native Method) - parking to wait for <0x00000005e8813020> (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@13-internal/LockSupport.java:235) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@13-internal/SynchronousQueue.java:462) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@13-internal/SynchronousQueue.java:361) at java.util.concurrent.SynchronousQueue.poll(java.base@13-internal/SynchronousQueue.java:937) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@13-internal/ThreadPoolExecutor.java:1053) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@13-internal/ThreadPoolExecutor.java:1114) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@13-internal/ThreadPoolExecutor.java:628) at java.lang.Thread.run(java.base@13-internal/Thread.java:835) "Attach Listener" #113 daemon prio=9 os_prio=0 cpu=112.06ms elapsed=13.93s tid=0x00007f3430001000 nid=0x4a42 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f3430001000 [0x4a42] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "VM Thread" os_prio=0 cpu=295.31ms elapsed=740.15s tid=0x00007f348447b000 nid=0x1966 runnable "GC Thread#0" os_prio=0 cpu=109.05ms elapsed=740.32s tid=0x00007f34840a1800 nid=0x1961 runnable "GC Thread#1" os_prio=0 cpu=59.18ms elapsed=575.43s tid=0x00007f3444009000 nid=0x24b7 runnable "GC Thread#2" os_prio=0 cpu=96.20ms elapsed=575.43s tid=0x00007f344400a800 nid=0x24b8 runnable "GC Thread#3" os_prio=0 cpu=35.58ms elapsed=575.43s tid=0x00007f344400c800 nid=0x24b9 runnable "GC Thread#4" os_prio=0 cpu=107.01ms elapsed=575.43s tid=0x00007f344400e000 nid=0x24ba runnable "GC Thread#5" os_prio=0 cpu=117.17ms elapsed=575.42s tid=0x00007f3444010000 nid=0x24bb runnable "G1 Main Marker" os_prio=0 cpu=1.18ms elapsed=740.31s tid=0x00007f34840d0000 nid=0x1962 runnable "G1 Conc#0" os_prio=0 cpu=0.11ms elapsed=740.30s tid=0x00007f34840d2800 nid=0x1963 runnable "G1 Refine#0" os_prio=0 cpu=0.95ms elapsed=740.26s tid=0x00007f3484306800 nid=0x1964 runnable "G1 Young RemSet Sampling" os_prio=0 cpu=254.66ms elapsed=740.25s tid=0x00007f3484309000 nid=0x1965 runnable "VM Periodic Task Thread" os_prio=0 cpu=501.77ms elapsed=739.59s tid=0x00007f348475c800 nid=0x1970 waiting on condition JNI global refs: 23, weak refs: 0 ---------------------------------------- [2019-02-06 07:17:13] exit code: 0 time: 613 ms ---------------------------------------- ---------------------------------------- [2019-02-06 07:16:38] [/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk13-jdk.327/linux-x64-debug.jdk/jdk-13/fastdebug/bin/jstack, 10167] timeout=20000 ---------------------------------------- 2019-02-06 07:16:39 Full thread dump Java HotSpot(TM) 64-Bit Server VM (13-internal+0-jdk13-jdk.327 mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00007ff8ec002e30, length=10, elements={ 0x00007ff94001d000, 0x00007ff940200000, 0x00007ff940202800, 0x00007ff94020b000, 0x00007ff94020d800, 0x00007ff940210000, 0x00007ff940212800, 0x00007ff94025c000, 0x00007ff94029f000, 0x00007ff8ec001000 } _java_thread_list_alloc_cnt=11, _java_thread_list_free_cnt=9, _java_thread_list_max=10, _nested_thread_list_max=1 _tlh_cnt=284, _tlh_times=0, avg_tlh_time=0.00, _tlh_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=520.76ms elapsed=492.42s tid=0x00007ff94001d000 nid=0x27ba runnable [0x00007ff949f3e000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff94001d000 [0x27ba] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at sun.tools.attach.VirtualMachineImpl.read(jdk.attach@13-internal/Native Method) at sun.tools.attach.VirtualMachineImpl$SocketInputStream.read(jdk.attach@13-internal/VirtualMachineImpl.java:260) - locked <0x000000062860bd60> (a sun.tools.attach.VirtualMachineImpl$SocketInputStream) at sun.tools.attach.HotSpotVirtualMachine.readInt(jdk.attach@13-internal/HotSpotVirtualMachine.java:328) at sun.tools.attach.VirtualMachineImpl.execute(jdk.attach@13-internal/VirtualMachineImpl.java:192) at sun.tools.attach.HotSpotVirtualMachine.executeCommand(jdk.attach@13-internal/HotSpotVirtualMachine.java:309) at sun.tools.attach.HotSpotVirtualMachine.executeJCmd(jdk.attach@13-internal/HotSpotVirtualMachine.java:291) at sun.tools.jcmd.JCmd.executeCommandForPid(jdk.jcmd@13-internal/JCmd.java:124) at sun.tools.jcmd.JCmd.main(jdk.jcmd@13-internal/JCmd.java:98) "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.64ms elapsed=492.29s tid=0x00007ff940200000 nid=0x27ec waiting on condition [0x00007ff90901b000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff940200000 [0x27ec] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ref.Reference.waitForReferencePendingList(java.base@13-internal/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@13-internal/Reference.java:241) at java.lang.ref.Reference$ReferenceHandler.run(java.base@13-internal/Reference.java:213) "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.41ms elapsed=492.28s tid=0x00007ff940202800 nid=0x27ee in Object.wait() [0x00007ff908f1a000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007ff940202800 [0x27ee] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@13-internal/Native Method) - waiting on <0x000000062860c630> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:155) - locked <0x000000062860c630> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:176) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@13-internal/Finalizer.java:170) "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.41ms elapsed=492.24s tid=0x00007ff94020b000 nid=0x27f6 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff94020b000 [0x27f6] 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=180.55ms elapsed=492.24s tid=0x00007ff94020d800 nid=0x27f7 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff94020d800 [0x27f7] 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=466.84ms elapsed=492.23s tid=0x00007ff940210000 nid=0x27f9 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff940210000 [0x27f9] 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=2.90ms elapsed=492.23s tid=0x00007ff940212800 nid=0x27fb runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff940212800 [0x27fb] 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=0.29ms elapsed=492.07s tid=0x00007ff94025c000 nid=0x2814 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff94025c000 [0x2814] 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=1.40ms elapsed=491.94s tid=0x00007ff94029f000 nid=0x281f in Object.wait() [0x00007ff9083eb000] java.lang.Thread.State: TIMED_WAITING (on object monitor) Thread: 0x00007ff94029f000 [0x281f] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait(java.base@13-internal/Native Method) - waiting on <0x000000062860cfe0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@13-internal/ReferenceQueue.java:155) - locked <0x000000062860cfe0> (a java.lang.ref.ReferenceQueue$Lock) at jdk.internal.ref.CleanerImpl.run(java.base@13-internal/CleanerImpl.java:148) at java.lang.Thread.run(java.base@13-internal/Thread.java:835) at jdk.internal.misc.InnocuousThread.run(java.base@13-internal/InnocuousThread.java:134) "Attach Listener" #11 daemon prio=9 os_prio=0 cpu=74.98ms elapsed=12.87s tid=0x00007ff8ec001000 nid=0x469a waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007ff8ec001000 [0x469a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "VM Thread" os_prio=0 cpu=59.49ms elapsed=492.31s tid=0x00007ff9401f7000 nid=0x27e7 runnable "GC Thread#0" os_prio=0 cpu=72.02ms elapsed=492.40s tid=0x00007ff9400a1000 nid=0x27bf runnable "GC Thread#1" os_prio=0 cpu=40.01ms elapsed=12.76s tid=0x00007ff900001000 nid=0x469b runnable "G1 Main Marker" os_prio=0 cpu=0.61ms elapsed=492.39s tid=0x00007ff9400d0000 nid=0x27c5 runnable "G1 Conc#0" os_prio=0 cpu=0.14ms elapsed=492.38s tid=0x00007ff9400d2000 nid=0x27c8 runnable "G1 Refine#0" os_prio=0 cpu=0.40ms elapsed=492.38s tid=0x00007ff9400f7000 nid=0x27cb runnable "G1 Young RemSet Sampling" os_prio=0 cpu=69.21ms elapsed=492.37s tid=0x00007ff9400f9000 nid=0x27cf runnable "VM Periodic Task Thread" os_prio=0 cpu=311.55ms elapsed=492.05s tid=0x00007ff940263800 nid=0x2819 waiting on condition JNI global refs: 8, weak refs: 0 ---------------------------------------- [2019-02-06 07:16:39] exit code: 0 time: 526 ms ----------------------------------------
06-02-2019
the failure doesn't happen that often, removing maintainer-pain label for now.
05-02-2019
It may not be at the level of maintainer pain and there are more than one intermittent test that raises questions about process termination. I would still add the diagnostic information into ProcessTools to give more information to any future failure. The diagnostic information would have provided information about the view that the Java runtime has of the processes. The separate and late information provided by the timeout handler is a good cross check but no substitute for knowing the process state as seen by the java runtime.
04-02-2019
while working on JDK-8218197, I tried to reproduce this test failure many-many times, including runs w/ the same flags, w/ the same flags and seed value, w/ the same flags, seed and on the same host. all in vain, the test doesn't want to time out. how often do we see it failing in CI? is it really often enough to be a maintainer-pain?
02-02-2019
given our latest finding, I'm moving this one back to hotspot/compiler.
02-02-2019
The thread dump looks normal. It has two "process reaper" threads and two threads Thread-47 and AgentVMThread waiting in Process.waitFor as expected. The process reaper threads are (presumably) blocked in native waitForProcessExit0 for waitpid().
01-02-2019
[~rriggs], here is a full thread dump, it is available in processes.html file stored in the test-work dir. ---------------------------------------- [2019-01-12 17:21:55] [/scratch/opt/mach5/mesos/work_dir/jib-master/install/jdk12-jdk.1214/linux-x64-debug.jdk/jdk-12/fastdebug/bin/jstack, 7047] timeout=20000 ---------------------------------------- 2019-01-12 17:21:55 Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-internal+0-jdk12-jdk.1214 mixed mode): Threads class SMR info: _java_thread_list=0x00007f6e480021c0, length=24, elements={ 0x00007f6eb001c000, 0x00007f6eb058a800, 0x00007f6eb0590000, 0x00007f6eb05db800, 0x00007f6eb05de000, 0x00007f6eb05e0800, 0x00007f6eb05f2800, 0x00007f6eb0690000, 0x00007f6eb085e000, 0x00007f6eb0943800, 0x00007f6e2c135800, 0x00007f6eb079f800, 0x00007f6e2c18a000, 0x00007f6e2c18f800, 0x00007f6e2c069000, 0x00007f6df8007800, 0x00007f6df800c800, 0x00007f6df800d800, 0x00007f6df800f800, 0x00007f6df8011800, 0x00007f6df8013800, 0x00007f6df8016000, 0x00007f6df8019000, 0x00007f6e48001000 } _java_thread_list_alloc_cnt=247, _java_thread_list_free_cnt=245, _java_thread_list_max=41, _nested_thread_list_max=1 _tlh_cnt=10398, _tlh_times=51, avg_tlh_time=0.00, _tlh_time_max=12 _deleted_thread_cnt=111, _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=999.09ms elapsed=2037.54s tid=0x00007f6eb001c000 nid=0x1b89 in Object.wait() [0x00007f6eba0d1000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f6eb001c000 [0x1b89] 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 <0x000000040bed8ef0> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1308) - locked <0x000000040bed8ef0> (a java.lang.Thread) at java.lang.Thread.join(java.base@12-internal/Thread.java:1375) at com.sun.javatest.regtest.agent.MainActionHelper.runClass(MainActionHelper.java:132) at com.sun.javatest.regtest.agent.AgentServer.doMain(AgentServer.java:247) at com.sun.javatest.regtest.agent.AgentServer.run(AgentServer.java:193) at com.sun.javatest.regtest.agent.AgentServer.main(AgentServer.java:65) "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1.44ms elapsed=2037.45s tid=0x00007f6eb058a800 nid=0x1b92 waiting on condition [0x00007f6eb423d000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb058a800 [0x1b92] 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=0.25ms elapsed=2037.45s tid=0x00007f6eb0590000 nid=0x1b93 in Object.wait() [0x00007f6eb413c000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f6eb0590000 [0x1b93] 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 <0x000000040bd567d0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155) - locked <0x000000040bd567d0> (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=0.62ms elapsed=2037.42s tid=0x00007f6eb05db800 nid=0x1b94 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb05db800 [0x1b94] 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=3410.35ms elapsed=2037.42s tid=0x00007f6eb05de000 nid=0x1b95 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb05de000 [0x1b95] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked No compile task "C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=3608.37ms elapsed=2037.42s tid=0x00007f6eb05e0800 nid=0x1b96 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb05e0800 [0x1b96] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked No compile task "Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=54.58ms elapsed=2037.41s tid=0x00007f6eb05f2800 nid=0x1b97 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb05f2800 [0x1b97] 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=5.47ms elapsed=2037.31s tid=0x00007f6eb0690000 nid=0x1b98 in Object.wait() [0x00007f6e74c66000] java.lang.Thread.State: TIMED_WAITING (on object monitor) Thread: 0x00007f6eb0690000 [0x1b98] 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 <0x000000040bce33a0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(java.base@12-internal/ReferenceQueue.java:155) - locked <0x000000040bce33a0> (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) "Service Thread" #11 daemon prio=9 os_prio=0 cpu=2.69ms elapsed=2037.12s tid=0x00007f6eb085e000 nid=0x1b9a runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6eb085e000 [0x1b9a] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "pool-1-thread-1" #12 daemon prio=5 os_prio=0 cpu=24.79ms elapsed=2036.84s tid=0x00007f6eb0943800 nid=0x1b9c waiting on condition [0x00007f6e74202000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f6eb0943800 [0x1b9c] 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 <0x000000040bce7730> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@12-internal/LockSupport.java:235) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@12-internal/AbstractQueuedSynchronizer.java:2123) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@12-internal/ScheduledThreadPoolExecutor.java:1182) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@12-internal/ScheduledThreadPoolExecutor.java:899) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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) "process reaper" #57 daemon prio=10 os_prio=0 cpu=2.10ms elapsed=1238.95s tid=0x00007f6e2c135800 nid=0x2b60 runnable [0x00007f6e74101000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6e2c135800 [0x2b60] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.lang.ProcessHandleImpl.waitForProcessExit0(java.base@12-internal/Native Method) at java.lang.ProcessHandleImpl$1.run(java.base@12-internal/ProcessHandleImpl.java:138) 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) "AgentVMThread" #91 prio=5 os_prio=0 cpu=372.85ms elapsed=1213.85s tid=0x00007f6eb079f800 nid=0x2da7 in Object.wait() [0x00007f6e7473c000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f6eb079f800 [0x2da7] 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 <0x000000040bcc0d70> (a java.lang.ProcessImpl) at java.lang.Object.wait(java.base@12-internal/Object.java:326) at java.lang.ProcessImpl.waitFor(java.base@12-internal/ProcessImpl.java:495) - locked <0x000000040bcc0d70> (a java.lang.ProcessImpl) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:374) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:350) at jdk.test.lib.process.ProcessTools.executeTestJvm(ProcessTools.java:331) at compiler.compilercontrol.share.scenario.Executor.execute(Executor.java:108) at compiler.compilercontrol.jcmd.StressAddJcmdBase.test(StressAddJcmdBase.java:71) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest.main(StressAddMultiThreadedTest.java:66) 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:567) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:246) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "Thread-47" #92 prio=5 os_prio=0 cpu=11.96ms elapsed=1213.17s tid=0x00007f6e2c18a000 nid=0x2dbc in Object.wait() [0x00007f6e64ba0000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f6e2c18a000 [0x2dbc] 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 <0x000000040bcb5ae8> (a java.lang.ProcessImpl) at java.lang.Object.wait(java.base@12-internal/Object.java:326) at java.lang.ProcessImpl.waitFor(java.base@12-internal/ProcessImpl.java:495) - locked <0x000000040bcb5ae8> (a java.lang.ProcessImpl) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:374) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:350) at jdk.test.lib.dcmd.JcmdExecutor.executeImpl(JcmdExecutor.java:49) at jdk.test.lib.dcmd.CommandExecutor.execute(CommandExecutor.java:61) at jdk.test.lib.dcmd.CommandExecutor.execute(CommandExecutor.java:43) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest.lambda$makeConnection$0(StressAddMultiThreadedTest.java:72) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest$$Lambda$304/0x00000007c01c9040.call(Unknown Source) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(java.base@12-internal/ThreadPoolExecutor.java:2027) at java.util.concurrent.ThreadPoolExecutor.reject(java.base@12-internal/ThreadPoolExecutor.java:825) at java.util.concurrent.ThreadPoolExecutor.execute(java.base@12-internal/ThreadPoolExecutor.java:1355) at java.util.concurrent.AbstractExecutorService.submit(java.base@12-internal/AbstractExecutorService.java:140) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest.makeConnection(StressAddMultiThreadedTest.java:71) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor.lambda$executeJCMD$0(StressAddJcmdBase.java:127) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor$$Lambda$303/0x00000007c01c8c40.call(Unknown Source) at jdk.test.lib.TimeLimitedRunner.call(TimeLimitedRunner.java:71) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor.executeJCMD(StressAddJcmdBase.java:129) at compiler.compilercontrol.share.scenario.Executor.connectTestVM(Executor.java:140) at compiler.compilercontrol.share.scenario.Executor.lambda$execute$0(Executor.java:100) at compiler.compilercontrol.share.scenario.Executor$$Lambda$300/0x00000007c01c8040.run(Unknown Source) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "Thread-48" #93 daemon prio=5 os_prio=0 cpu=1.43ms elapsed=1213.06s tid=0x00007f6e2c18f800 nid=0x2dc5 runnable [0x00007f6e64ca2000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6e2c18f800 [0x2dc5] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.io.FileInputStream.readBytes(java.base@12-internal/Native Method) at java.io.FileInputStream.read(java.base@12-internal/FileInputStream.java:273) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:290) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bcc2e68> (a java.lang.ProcessImpl$ProcessPipeInputStream) at java.io.BufferedInputStream.fill(java.base@12-internal/BufferedInputStream.java:252) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:292) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040be9eb68> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(java.base@12-internal/FilterInputStream.java:107) at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-internal/Executors.java:515) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "Thread-49" #94 daemon prio=5 os_prio=0 cpu=1.00ms elapsed=1213.03s tid=0x00007f6e2c069000 nid=0x2dc9 runnable [0x00007f6e651ae000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6e2c069000 [0x2dc9] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.io.FileInputStream.readBytes(java.base@12-internal/Native Method) at java.io.FileInputStream.read(java.base@12-internal/FileInputStream.java:273) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:290) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bcc4f08> (a java.lang.ProcessImpl$ProcessPipeInputStream) at java.io.BufferedInputStream.fill(java.base@12-internal/BufferedInputStream.java:252) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:292) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bca5ab0> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(java.base@12-internal/FilterInputStream.java:107) at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-internal/Executors.java:515) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "pool-2-thread-1" #95 prio=5 os_prio=0 cpu=9.70ms elapsed=1211.57s tid=0x00007f6df8007800 nid=0x2de8 waiting on condition [0x00007f6e6479f000] java.lang.Thread.State: WAITING (parking) Thread: 0x00007f6df8007800 [0x2de8] 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 <0x000000040bea4598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12-internal/AbstractQueuedSynchronizer.java:2081) at java.util.concurrent.ArrayBlockingQueue.take(java.base@12-internal/ArrayBlockingQueue.java:417) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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-2-thread-2" #96 prio=5 os_prio=0 cpu=70.44ms elapsed=1211.57s tid=0x00007f6df800c800 nid=0x2de9 waiting on condition [0x00007f6e652af000] java.lang.Thread.State: WAITING (parking) Thread: 0x00007f6df800c800 [0x2de9] 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 <0x000000040bea4598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12-internal/AbstractQueuedSynchronizer.java:2081) at java.util.concurrent.ArrayBlockingQueue.take(java.base@12-internal/ArrayBlockingQueue.java:417) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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-2-thread-3" #97 prio=5 os_prio=0 cpu=6.43ms elapsed=1211.56s tid=0x00007f6df800d800 nid=0x2dea waiting on condition [0x00007f6e648a0000] java.lang.Thread.State: WAITING (parking) Thread: 0x00007f6df800d800 [0x2dea] 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 <0x000000040bea4598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12-internal/AbstractQueuedSynchronizer.java:2081) at java.util.concurrent.ArrayBlockingQueue.take(java.base@12-internal/ArrayBlockingQueue.java:417) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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-2-thread-4" #98 prio=5 os_prio=0 cpu=5.30ms elapsed=1211.56s tid=0x00007f6df800f800 nid=0x2deb waiting on condition [0x00007f6e6469e000] java.lang.Thread.State: WAITING (parking) Thread: 0x00007f6df800f800 [0x2deb] 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 <0x000000040bea4598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12-internal/AbstractQueuedSynchronizer.java:2081) at java.util.concurrent.ArrayBlockingQueue.take(java.base@12-internal/ArrayBlockingQueue.java:417) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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-2-thread-5" #99 prio=5 os_prio=0 cpu=5.86ms elapsed=1211.56s tid=0x00007f6df8011800 nid=0x2dec waiting on condition [0x00007f6e6459d000] java.lang.Thread.State: WAITING (parking) Thread: 0x00007f6df8011800 [0x2dec] 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 <0x000000040bea4598> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@12-internal/AbstractQueuedSynchronizer.java:2081) at java.util.concurrent.ArrayBlockingQueue.take(java.base@12-internal/ArrayBlockingQueue.java:417) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@12-internal/ThreadPoolExecutor.java:1054) 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) "process reaper" #104 daemon prio=10 os_prio=0 cpu=0.25ms elapsed=1211.51s tid=0x00007f6df8013800 nid=0x2e07 runnable [0x00007f6e7404d000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6df8013800 [0x2e07] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.lang.ProcessHandleImpl.waitForProcessExit0(java.base@12-internal/Native Method) at java.lang.ProcessHandleImpl$1.run(java.base@12-internal/ProcessHandleImpl.java:138) 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) "Thread-58" #112 daemon prio=5 os_prio=0 cpu=1.27ms elapsed=1211.49s tid=0x00007f6df8016000 nid=0x2e20 runnable [0x00007f6dcfcfb000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6df8016000 [0x2e20] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.io.FileInputStream.readBytes(java.base@12-internal/Native Method) at java.io.FileInputStream.read(java.base@12-internal/FileInputStream.java:273) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:290) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bcb7be0> (a java.lang.ProcessImpl$ProcessPipeInputStream) at java.io.BufferedInputStream.fill(java.base@12-internal/BufferedInputStream.java:252) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:292) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bca12b8> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(java.base@12-internal/FilterInputStream.java:107) at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-internal/Executors.java:515) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "Thread-59" #113 daemon prio=5 os_prio=0 cpu=0.98ms elapsed=1211.47s tid=0x00007f6df8019000 nid=0x2e23 runnable [0x00007f6dcfbfa000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6df8019000 [0x2e23] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_in_native at java.io.FileInputStream.readBytes(java.base@12-internal/Native Method) at java.io.FileInputStream.read(java.base@12-internal/FileInputStream.java:273) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:290) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bcb9c80> (a java.lang.ProcessImpl$ProcessPipeInputStream) at java.io.BufferedInputStream.fill(java.base@12-internal/BufferedInputStream.java:252) at java.io.BufferedInputStream.read1(java.base@12-internal/BufferedInputStream.java:292) at java.io.BufferedInputStream.read(java.base@12-internal/BufferedInputStream.java:351) - locked <0x000000040bca3458> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(java.base@12-internal/FilterInputStream.java:107) at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-internal/Executors.java:515) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) "Attach Listener" #128 daemon prio=9 os_prio=0 cpu=91.65ms elapsed=12.96s tid=0x00007f6e48001000 nid=0x4c9c waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f6e48001000 [0x4c9c] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked "VM Thread" os_prio=0 cpu=340.40ms elapsed=2037.46s tid=0x00007f6eb0566000 nid=0x1b91 runnable "GC Thread#0" os_prio=0 cpu=34.46ms elapsed=2037.54s tid=0x00007f6eb0097000 nid=0x1b8c runnable "GC Thread#1" os_prio=0 cpu=28.61ms elapsed=1380.90s tid=0x00007f6e5c001000 nid=0x26a3 runnable "GC Thread#2" os_prio=0 cpu=198.56ms elapsed=1380.90s tid=0x00007f6e5c002000 nid=0x26a4 runnable "GC Thread#3" os_prio=0 cpu=177.10ms elapsed=1380.90s tid=0x00007f6e5c003000 nid=0x26a5 runnable "GC Thread#4" os_prio=0 cpu=208.40ms elapsed=1380.90s tid=0x00007f6e5c004800 nid=0x26a6 runnable "GC Thread#5" os_prio=0 cpu=21.93ms elapsed=1380.90s tid=0x00007f6e5c005800 nid=0x26a7 runnable "GC Thread#6" os_prio=0 cpu=24.29ms elapsed=1380.90s tid=0x00007f6e5c007000 nid=0x26a8 runnable "GC Thread#7" os_prio=0 cpu=26.36ms elapsed=1380.90s tid=0x00007f6e5c009800 nid=0x26a9 runnable "G1 Main Marker" os_prio=0 cpu=1.20ms elapsed=2037.54s tid=0x00007f6eb00c6000 nid=0x1b8d runnable "G1 Conc#0" os_prio=0 cpu=0.08ms elapsed=2037.54s tid=0x00007f6eb00c8800 nid=0x1b8e runnable "G1 Refine#0" os_prio=0 cpu=1.20ms elapsed=2037.53s tid=0x00007f6eb03f1000 nid=0x1b8f runnable "G1 Young RemSet Sampling" os_prio=0 cpu=541.54ms elapsed=2037.53s tid=0x00007f6eb03f3000 nid=0x1b90 runnable "VM Periodic Task Thread" os_prio=0 cpu=1191.32ms elapsed=2037.09s tid=0x00007f6eb0870000 nid=0x1b9b waiting on condition JNI global refs: 24, weak refs: 0 ---------------------------------------- [2019-01-12 17:21:55] exit code: 0 time: 514 ms ----------------------------------------
01-02-2019
Process.waitFor depends on a separate thread to wait for the process to exit. I didn't see a full thread dump (to check on that thread) in the logs but would be interested if there is one. I have a patch to add diagnostic information to ProcessTools.executeProcess. It does a timed waitFor and uses ProcessHandle.isAlive to verify using a different technique if the process is alive. Some of the messages (from jtreg) don't include the pids of the processes the process tree is not always clear.
01-02-2019
yes, this will be the most logical and probable explanation. I'm working on the fix for the timeout handler, will file a bug shortly.
01-02-2019
So this appears to just be a normal timeout (cause of which still needs further investigation) but our diagnostics is what caused the puzzling case of the vanishing children :)
01-02-2019
just crossed my mind, after JDK-8205687 we kill a process to get a core dump, and we gather info from the parent process before its children, and killing a parent can kill children. this will explain all the evidences.
01-02-2019
[~dholmes], I agree w/ you that there is no direct evidence that Process::waitFor doesn't return, your explanation is very much alike to the one I gave in JDK-8217170. we however have 3 different tests which seem to timeout in the same way, they wait for a child process, but by the time timeouthandler starts to gather an info from the child process, it is gone. please note, in all 3 cases, we don't see a child process exiting while we are gathering its information, they are always unavailable when we start to look at them. yes, I understand that it does't proof anything and there is a probability that it's just a coincidence that we haven't observed other states and eventually we might see child process exiting in the middle of timeout handler's work, but so far a bug in Process::waitFor seems to be more likely. if someone has ideas on how we can improve diagnostic here, I'd be happy to work on it.
01-02-2019
[~rriggs] Roger, although I don't think this test is the easiest to understand comparing w/ gc/g1/TestLargePageUseForAuxMemory.java and/or gc/arguments/TestUseCompressedOopsErgo.java (which are believed to fail due to the same issue), I can try to explain it. in JVM_1, jtreg starts the test main class, compiler.compilercontrol.jcmd.StressAddMultiThreadedTest, which opens a socket, starts compiler.compilercontrol.share.actions.BaseAction class w/ socket port as an argument in a new JVM -- JVM_2, starts a new thread (connectTestVM) and waits for JVM_2 to finish. JVM_2 gets its own pid, send via socket back to the 1st JVM and waits for a line from the socket. connectTestVM thread in JVM_1 reads JVM_2's pid from the socket, N time starts jcmd process (which connects to JVM_2 by its pid and sends one compiler directive-related jcmd command), waits for jcmd process to finish, after all Nth jcmd process is finished, JVM_1 sends an empty line via socket. as soon as JVM_2 receives a line, it exists. in the data I posted above, 7047 is JVM_1, 11713 -- JVM_2, and I assume that 11759 is a jcmd process. jtreg was run w/ -agentvm and -concurrency:4. as jtreg only starts JVM_1, I don't think -othervm have any effect, but we didn't try to run reproduce it -othervm. there is nothing in the test code which can terminate the child process, it only uses ProcessTools to start them and wait for them to finish. the only other process which can terminate these processes would be jtreg, or infra above it, but there are no evidence they were involved. as I explained above, the test main JVM starts jcmd processes which connect to a child JVM, other than that nothing should try to attach to the processes till timeout happens. then timeout happens, jtreg runs the timeout handler which will attach to the processes in order to gather diagnostic information. Hope this makes it more clear, please let me know if you need more details.
01-02-2019
There are too many processes involved here to determine where exactly the problem is arising. We appear to have a process waiting for a child process that is no longer in existence when the timeout handler dumps the process information. but that in itself doesn't tell us much as the child process could terminate normally after the timeout handler does the stack dump of the parent that shows it waiting for the child. There's no direct evidence that Process.waitFor has failed to return AFAICS.
01-02-2019
Who can explain all of the activity, processes and the dynamics going here? What role is jtreg playing in process launching, what is the concurrency level? Does it happen when not using agentvm mode? Is it possible that some process other than the ProcessTools and Process.waitFor() handles the child termination and swallows the exit code. Is another process, like dbx, attaching to the process?
01-02-2019
moving to core-libs/java.lang as it seems to be the same issue as JDK-8217170.
31-01-2019
according to the info gathered by timeout-handler, the main test process waits for a child process to finish[1], and ps returns 2 child processes[2], however gcc wasn't able to attach to either of them due to missed /proc files[3,4], and kill -ABRT for them exited w/ 'No such process'[5,6]. this makes me think it's another manifestation of JDK-8217170. [1] "Thread-47" #92 prio=5 os_prio=0 cpu=11.96ms elapsed=1213.17s tid=0x00007f6e2c18a000 nid=0x2dbc in Object.wait() [0x00007f6e64ba0000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f6e2c18a000 [0x2dbc] 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 <0x000000040bcb5ae8> (a java.lang.ProcessImpl) at java.lang.Object.wait(java.base@12-internal/Object.java:326) at java.lang.ProcessImpl.waitFor(java.base@12-internal/ProcessImpl.java:495) - locked <0x000000040bcb5ae8> (a java.lang.ProcessImpl) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:374) at jdk.test.lib.process.ProcessTools.executeProcess(ProcessTools.java:350) at jdk.test.lib.dcmd.JcmdExecutor.executeImpl(JcmdExecutor.java:49) at jdk.test.lib.dcmd.CommandExecutor.execute(CommandExecutor.java:61) at jdk.test.lib.dcmd.CommandExecutor.execute(CommandExecutor.java:43) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest.lambda$makeConnection$0(StressAddMultiThreadedTest.java:72) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest$$Lambda$304/0x00000007c01c9040.call(Unknown Source) at java.util.concurrent.FutureTask.run(java.base@12-internal/FutureTask.java:264) at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(java.base@12-internal/ThreadPoolExecutor.java:2027) at java.util.concurrent.ThreadPoolExecutor.reject(java.base@12-internal/ThreadPoolExecutor.java:825) at java.util.concurrent.ThreadPoolExecutor.execute(java.base@12-internal/ThreadPoolExecutor.java:1355) at java.util.concurrent.AbstractExecutorService.submit(java.base@12-internal/AbstractExecutorService.java:140) at compiler.compilercontrol.jcmd.StressAddMultiThreadedTest.makeConnection(StressAddMultiThreadedTest.java:71) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor.lambda$executeJCMD$0(StressAddJcmdBase.java:127) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor$$Lambda$303/0x00000007c01c8c40.call(Unknown Source) at jdk.test.lib.TimeLimitedRunner.call(TimeLimitedRunner.java:71) at compiler.compilercontrol.jcmd.StressAddJcmdBase$TimeLimitedExecutor.executeJCMD(StressAddJcmdBase.java:129) at compiler.compilercontrol.share.scenario.Executor.connectTestVM(Executor.java:140) at compiler.compilercontrol.share.scenario.Executor.lambda$execute$0(Executor.java:100) at compiler.compilercontrol.share.scenario.Executor$$Lambda$300/0x00000007c01c8040.run(Unknown Source) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) [2]children ---------------------------------------- [2019-01-12 17:21:41] [/bin/ps, --no-headers, -o, pid, --ppid, 7047] timeout=20000 ---------------------------------------- ---------------------------------------- [2019-01-12 17:21:41] exit code: 0 time: 14 ms ---------------------------------------- 11713 11759 [3] iteration_0 ---------------------------------------- [2019-01-12 17:22:10] [/bin/gdb, --pid=11713, -batch, -ex, thread apply all backtrace] timeout=20000 ---------------------------------------- warning: unable to open /proc file '/proc/11713/status' warning: unable to open /proc file '/proc/11713/status' ptrace: No such process. ---------------------------------------- [2019-01-12 17:22:10] exit code: 0 time: 24 ms ---------------------------------------- [4] ---------------------------------------- [2019-01-12 17:22:19] [/bin/gdb, --pid=11759, -batch, -ex, thread apply all backtrace] timeout=20000 ---------------------------------------- warning: unable to open /proc file '/proc/11759/status' warning: unable to open /proc file '/proc/11759/status' ptrace: No such process. ---------------------------------------- [2019-01-12 17:22:19] exit code: 0 time: 25 ms ---------------------------------------- [5] ---------------------------------------- [2019-01-12 17:22:13] [/bin/kill, -ABRT, 11713] timeout=20000 ---------------------------------------- kill: sending signal to 11713 failed: No such process ---------------------------------------- [2019-01-12 17:22:13] exit code: 1 time: 1 ms ---------------------------------------- [6] ---------------------------------------- [2019-01-12 17:22:21] [/bin/kill, -ABRT, 11759] timeout=20000 ---------------------------------------- kill: sending signal to 11759 failed: No such process ---------------------------------------- [2019-01-12 17:22:21] exit code: 1 time: 1 ms ----------------------------------------
31-01-2019
Igor, could you please have a look?
04-06-2018
Please feel free to change to correct assignee. Thanks
04-06-2018
ILW = Test timeout, single test (intermittent), no workaround = MLH = P4
06-03-2017