Hi Sergey,
Here's the stacktrace on timeout. It seems that robot events are not
processed so EDT hangs and jtreg test did not finish. Calling
waitForIdle() probably allow those events to process.
Timeout information:
Running jstack on process 16896
2018-02-14 10:57:56
Full thread dump Java HotSpot(TM) 64-Bit Server VM (10-ea+41 mixed mode):
Threads class SMR info:
_java_thread_list=0x000001b8718ef900, length=18, elements={
0x000001b83d8ad000, 0x000001b865155800, 0x000001b865156800, 0x000001b8651b6800,
0x000001b8651b7000, 0x000001b8651bc000, 0x000001b8651be800, 0x000001b8651bf800,
0x000001b8651d3800, 0x000001b8651c8800, 0x000001b865774000, 0x000001b865895000,
0x000001b86592e800, 0x000001b865cb9000, 0x000001b8656fb000, 0x000001b865a39800,
0x000001b865b79000, 0x000001b871cc1000
}
"main" #1 prio=5 os_prio=0 tid=0x000001b83d8ad000 nid=0x3e84 in Object.wait() [0x0000003e642fe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base at 10-ea/Native Method)
- waiting on <0x00000006d2880200> (a java.lang.Thread)
at java.lang.Thread.join(java.base at 10-ea/Thread.java:1353)
- waiting to re-lock in wait() <0x00000006d2880200> (a java.lang.Thread)
at java.lang.Thread.join(java.base at 10-ea/Thread.java:1427)
at java.lang.ApplicationShutdownHooks.runHooks(java.base at 10-ea/ApplicationShutdownHooks.java:107)
at java.lang.ApplicationShutdownHooks$1.run(java.base at 10-ea/ApplicationShutdownHooks.java:46)
at java.lang.Shutdown.runHooks(java.base at 10-ea/Shutdown.java:123)
at java.lang.Shutdown.sequence(java.base at 10-ea/Shutdown.java:167)
at java.lang.Shutdown.exit(java.base at 10-ea/Shutdown.java:212)
- locked <0x00000006d28858b8> (a java.lang.Class for java.lang.Shutdown)
at java.lang.Runtime.exit(java.base at 10-ea/Runtime.java:118)
at java.lang.System.exit(java.base at 10-ea/System.java:1720)
at com.sun.javatest.regtest.agent.AStatus.exit(AStatus.java:199)
at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:83)
"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x000001b865155800 nid=0x4f54 waiting on condition [0x0000003e658fe000]
java.lang.Thread.State: RUNNABLE
at java.lang.ref.Reference.waitForReferencePendingList(java.base at 10-ea/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base at 10-ea/Reference.java:174)
at java.lang.ref.Reference.access$000(java.base at 10-ea/Reference.java:44)
at java.lang.ref.Reference$ReferenceHandler.run(java.base at 10-ea/Reference.java:138)
"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000001b865156800 nid=0x1518 in Object.wait() [0x0000003e659fe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base at 10-ea/Native Method)
- waiting on <0x00000006d2f09408> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base at 10-ea/ReferenceQueue.java:151)
- waiting to re-lock in wait() <0x00000006d2f09408> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base at 10-ea/ReferenceQueue.java:172)
at java.lang.ref.Finalizer$FinalizerThread.run(java.base at 10-ea/Finalizer.java:216)
"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x000001b8651b6800 nid=0x562c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000001b8651b7000 nid=0x40a8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x000001b8651bc000 nid=0x5388 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x000001b8651be800 nid=0xa44 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C2 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x000001b8651bf800 nid=0x1744 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C1 CompilerThread3" #9 daemon prio=9 os_prio=2 tid=0x000001b8651d3800 nid=0x2f68 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"Sweeper thread" #10 daemon prio=9 os_prio=2 tid=0x000001b8651c8800 nid=0x4fb4 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Service Thread" #11 daemon prio=9 os_prio=0 tid=0x000001b865774000 nid=0x5da4 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Common-Cleaner" #12 daemon prio=8 os_prio=1 tid=0x000001b865895000 nid=0x5218 in Object.wait() [0x0000003e663ff000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base at 10-ea/Native Method)
- waiting on <0x00000006d2ee5f38> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base at 10-ea/ReferenceQueue.java:151)
- waiting to re-lock in wait() <0x00000006d2ee5f38> (a java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base at 10-ea/CleanerImpl.java:148)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
at jdk.internal.misc.InnocuousThread.run(java.base at 10-ea/InnocuousThread.java:134)
"Java2D Disposer" #15 daemon prio=10 os_prio=2 tid=0x000001b86592e800 nid=0x1294 in Object.wait() [0x0000003e665ff000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base at 10-ea/Native Method)
- waiting on <0x00000006d2a00908> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base at 10-ea/ReferenceQueue.java:151)
- waiting to re-lock in wait() <0x00000006d2a00908> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base at 10-ea/ReferenceQueue.java:172)
at sun.java2d.Disposer.run(java.desktop at 10-ea/Disposer.java:144)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
"AWT-Shutdown" #16 prio=5 os_prio=0 tid=0x000001b865cb9000 nid=0x1250 in Object.wait() [0x0000003e666ff000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base at 10-ea/Native Method)
- waiting on <0x00000006d286d188> (a java.lang.Object)
at java.lang.Object.wait(java.base at 10-ea/Object.java:328)
at sun.awt.AWTAutoShutdown.run(java.desktop at 10-ea/AWTAutoShutdown.java:291)
- waiting to re-lock in wait() <0x00000006d286d188> (a java.lang.Object)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
"AWT-Windows" #17 daemon prio=6 os_prio=0 tid=0x000001b8656fb000 nid=0x423c runnable [0x0000003e667fe000]
java.lang.Thread.State: RUNNABLE
at sun.awt.windows.WToolkit.eventLoop(java.desktop at 10-ea/Native Method)
at sun.awt.windows.WToolkit.run(java.desktop at 10-ea/WToolkit.java:301)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
"AWT-EventQueue-0" #19 prio=6 os_prio=0 tid=0x000001b865a39800 nid=0x4624 waiting on condition [0x0000003e668fe000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base at 10-ea/Native Method)
- parking to wait for <0x00000006d2744b20> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base at 10-ea/LockSupport.java:194)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base at 10-ea/AbstractQueuedSynchronizer.java:2075)
at java.awt.EventQueue.getNextEvent(java.desktop at 10-ea/EventQueue.java:566)
at java.awt.EventDispatchThread.pumpOneEventForFilters(java.desktop at 10-ea/EventDispatchThread.java:190)
at java.awt.EventDispatchThread.pumpEventsForFilter(java.desktop at 10-ea/EventDispatchThread.java:124)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(java.desktop at 10-ea/EventDispatchThread.java:113)
at java.awt.EventDispatchThread.pumpEvents(java.desktop at 10-ea/EventDispatchThread.java:109)
at java.awt.EventDispatchThread.pumpEvents(java.desktop at 10-ea/EventDispatchThread.java:101)
at java.awt.EventDispatchThread.run(java.desktop at 10-ea/EventDispatchThread.java:90)
"TimerQueue" #20 daemon prio=5 os_prio=0 tid=0x000001b865b79000 nid=0x5b90 waiting on condition [0x0000003e669fe000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base at 10-ea/Native Method)
- parking to wait for <0x00000006d24b2df8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base at 10-ea/LockSupport.java:194)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base at 10-ea/AbstractQueuedSynchronizer.java:2075)
at java.util.concurrent.DelayQueue.take(java.base at 10-ea/DelayQueue.java:217)
at javax.swing.TimerQueue.run(java.desktop at 10-ea/TimerQueue.java:171)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
"ToolkitShutdown" #18 daemon prio=6 os_prio=0 tid=0x000001b871cc1000 nid=0x50c4 runnable [0x0000003e66fff000]
java.lang.Thread.State: RUNNABLE
at sun.awt.windows.WToolkit.shutdown(java.desktop at 10-ea/Native Method)
at sun.awt.windows.WToolkit$$Lambda$13/1860234640.run(java.desktop at 10-ea/Unknown Source)
at java.lang.Thread.run(java.base at 10-ea/Thread.java:844)
"VM Thread" os_prio=2 tid=0x000001b86514f000 nid=0x4e10 runnable
"GC Thread#0" os_prio=2 tid=0x000001b83d8c3800 nid=0x45d8 runnable
"GC Thread#1" os_prio=2 tid=0x000001b83d8c5800 nid=0x760 runnable
"GC Thread#2" os_prio=2 tid=0x000001b83d8c7800 nid=0x5368 runnable
"GC Thread#3" os_prio=2 tid=0x000001b83d8cb000 nid=0x5504 runnable
"GC Thread#4" os_prio=2 tid=0x000001b83d8cc800 nid=0x4bec runnable
"GC Thread#5" os_prio=2 tid=0x000001b83d8d6800 nid=0x4d74 runnable
"GC Thread#6" os_prio=2 tid=0x000001b83d8d2800 nid=0x472c runnable
"GC Thread#7" os_prio=2 tid=0x000001b83d8d7000 nid=0x5d10 runnable
"G1 Main Marker" os_prio=2 tid=0x000001b83d92d800 nid=0x17b4 runnable
"G1 Conc#0" os_prio=2 tid=0x000001b83d8d3000 nid=0x55ec runnable
"G1 Conc#1" os_prio=2 tid=0x000001b83d8d3800 nid=0x4790 runnable
"G1 Refine#0" os_prio=2 tid=0x000001b861e3e000 nid=0x4f4c runnable
"G1 Refine#1" os_prio=2 tid=0x000001b861e3f000 nid=0x5014 runnable
"G1 Refine#2" os_prio=2 tid=0x000001b861e42000 nid=0x3adc runnable
"G1 Refine#3" os_prio=2 tid=0x000001b861e47000 nid=0x4ba8 runnable
"G1 Refine#4" os_prio=2 tid=0x000001b83d8d4800 nid=0x498c runnable
"G1 Refine#5" os_prio=2 tid=0x000001b83d8d1000 nid=0x5e04 runnable
"G1 Refine#6" os_prio=2 tid=0x000001b83d8d7800 nid=0x398c runnable
"G1 Refine#7" os_prio=2 tid=0x000001b83d8d8800 nid=0x55d4 runnable
"G1 Young RemSet Sampling" os_prio=2 tid=0x000001b861e5a000 nid=0x4948 runnable
"VM Periodic Task Thread" os_prio=2 tid=0x000001b8653d4000 nid=0x4958 waiting on condition
JNI global references: 181
--- Timeout information end.
On 2/14/2018 3:56 AM, Sergey Bylokhov wrote:
> Hi, Prasanta.
> Did you have a chance to get a stack trace on timeout? The change in
> the tests are correct but it is unclear in what place the test may
> hang and why the changes fixed it.
>
> On 13/02/2018 01:22, Prasanta Sadhukhan wrote:
>> Hi All,
>>
>> Please review a testfix seen in the recent sprint-run, whereby the
>> test seems to times out .
>> Seems like test is issuing mouse events without waiting for robot to
>> process those events.
>> Enhance the test to allow robot to process the events and also
>> dispose of the frame once done,
>> so it should not bother other tests when run in bunch.
>>
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8197825
>> webrev: http://cr.openjdk.java.net/~psadhukhan/8197825/webrev.00/
>>
>> Regards
>> Prasanta
>
>