Modify

Opened 3 years ago

Closed 3 years ago

#12974 closed defect (fixed)

[Patch] Unit tests hang

Reported by: Don-vip Owned by: team
Priority: blocker Milestone: 16.06
Component: Unit tests Version:
Keywords: regression gsoc-core Cc: wiktorn, michael2402, bastiK

Description

It seems r10391 causes unit tests to hang:
https://josm.openstreetmap.de/jenkins/job/JOSM/jdk=JDK8/1416/ took 6 hours, only because I killed the process.
This is not solved in r10394 but at least this time I was able to get a thread dump:
https://josm.openstreetmap.de/jenkins/job/JOSM/jdk=JDK8/1417/console#ant-target-17

Extract:

    [junit] "AWT-EventQueue-0" #21 prio=6 os_prio=0 tid=0x00007f97e83b0000 nid=0xa43 waiting for monitor entry [0x00007f978fae6000]
    [junit]    java.lang.Thread.State: BLOCKED (on object monitor)
    [junit] 	at org.openstreetmap.josm.gui.layer.MainLayerManager.getActiveLayer(MainLayerManager.java)
    [junit] 	- waiting to lock <0x00000006c5223dc0> (a org.openstreetmap.josm.gui.layer.MainLayerManager)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.layer.ActivateLayerAction.isActiveLayer(ActivateLayerAction.java:84)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.layer.ActivateLayerAction$1.run(ActivateLayerAction.java:97)
    [junit] 	at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:301)
    [junit] 	at java.awt.EventQueue.dispatchEventImpl(EventQueue.java:756)
    [junit] 	at java.awt.EventQueue.access$500(EventQueue.java:97)
    [junit] 	at java.awt.EventQueue$3.run(EventQueue.java:709)
    [junit] 	at java.awt.EventQueue$3.run(EventQueue.java:703)
    [junit] 	at java.security.AccessController.doPrivileged(Native Method)
    [junit] 	at java.security.ProtectionDomain$JavaSecurityAccessImpl.doIntersectionPrivilege(ProtectionDomain.java:76)
    [junit] 	at java.awt.EventQueue.dispatchEvent(EventQueue.java:726)
    [junit] 	at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:201)
    [junit] 	at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:116)
    [junit] 	at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:105)
    [junit] 	at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:101)
    [junit] 	at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:93)
    [junit] 	at java.awt.EventDispatchThread.run(EventDispatchThread.java:82)


[junit] "main" #1 prio=5 os_prio=0 tid=0x00007f97e800c800 nid=0xa27 in Object.wait() [0x00007f97efbcc000]
    [junit]    java.lang.Thread.State: WAITING (on object monitor)
    [junit] 	at java.lang.Object.wait(Native Method)
    [junit] 	at java.lang.Object.wait(Object.java:502)
    [junit] 	at java.awt.EventQueue.invokeAndWait(EventQueue.java:1315)
    [junit] 	- locked <0x0000000778436010> (a java.awt.EventQueue$1AWTInvocationLock)
    [junit] 	at java.awt.EventQueue.invokeAndWait(EventQueue.java:1296)
    [junit] 	at javax.swing.SwingUtilities.invokeAndWait(SwingUtilities.java:1348)
    [junit] 	at org.openstreetmap.josm.gui.util.GuiHelper.runInEDTAndWait(GuiHelper.java:127)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.layer.ActivateLayerAction.updateEnabledState(ActivateLayerAction.java:89)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.LayerListDialog$3.valueChanged(LayerListDialog.java:366)
    [junit] 	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:184)
    [junit] 	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:164)
    [junit] 	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:211)
    [junit] 	at javax.swing.DefaultListSelectionModel.changeSelection(DefaultListSelectionModel.java:405)
    [junit] 	at javax.swing.DefaultListSelectionModel.changeSelection(DefaultListSelectionModel.java:415)
    [junit] 	at javax.swing.DefaultListSelectionModel.setSelectionInterval(DefaultListSelectionModel.java:459)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.LayerListDialog$LayerListModel.ensureActiveSelected(LayerListDialog.java:969)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.LayerListDialog$LayerListModel.activeOrEditLayerChanged(LayerListDialog.java:1088)
    [junit] 	at org.openstreetmap.josm.gui.layer.MainLayerManager.addAndFireActiveLayerChangeListener(MainLayerManager.java:143)
    [junit] 	- locked <0x00000006c5223dc0> (a org.openstreetmap.josm.gui.layer.MainLayerManager)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.LayerListDialog.showNotify(LayerListDialog.java:334)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.DialogsPanel.add(DialogsPanel.java:110)
    [junit] 	at org.openstreetmap.josm.gui.dialogs.DialogsPanel.initialize(DialogsPanel.java:60)
    [junit] 	at org.openstreetmap.josm.gui.MapFrame.initializeDialogsPane(MapFrame.java:364)
    [junit] 	at org.openstreetmap.josm.Main.createMapFrame(Main.java:837)
    [junit] 	- locked <0x00000006c5a3c4c8> (a org.openstreetmap.josm.gui.MainApplication)
    [junit] 	at org.openstreetmap.josm.JOSMFixture.init(JOSMFixture.java:124)
    [junit] 	at org.openstreetmap.josm.actions.AlignInLineActionTest.setUp(AlignInLineActionTest.java:33)
    [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:498)
    [junit] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    [junit] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    [junit] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    [junit] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
    [junit] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    [junit] 	at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1004)

Attachments (2)

patch-fix-12974.patch (4.0 KB) - added by michael2402 3 years ago.
patch-fix-12974-2.patch (8.9 KB) - added by michael2402 3 years ago.

Download all attachments as: .zip

Change History (13)

comment:1 Changed 3 years ago by michael2402

Should there be any guarantee on the thread that showNotify/hideNotify is called in?

JOSM normally calls them in the EDT Thread. This is why JOSM froze. I let JOSMFixture initialize all GUI related stuff in the EDT Thread.

I also removed synchronization of addLayer(). This is done by the layer manager now.

I force all calls to createMapFrame to be on the EDT Thread.

comment:2 Changed 3 years ago by michael2402

Keywords: gsoc-core added
Summary: Unit tests hang[Patch] Unit tests hang

comment:3 Changed 3 years ago by Don-vip

wrong patch :)

Changed 3 years ago by michael2402

Attachment: patch-fix-12974.patch added

comment:4 Changed 3 years ago by michael2402

Thanks, this is the right one...

comment:5 Changed 3 years ago by Don-vip

Resolution: fixed
Status: newclosed

In 10400/josm:

fix #12974 - Unit tests hang (patch by michael2402) - gsoc-core

comment:6 Changed 3 years ago by Don-vip

thanks! it works on my machine, I'm going to re-enable Jenkins job now.

comment:7 Changed 3 years ago by Don-vip

Resolution: fixed
Status: closedreopened

It seems tests hang again after #13001 / r10432:

[junit] Running org.openstreetmap.josm.actions.SelectByInternalPointActionTest

(hang)

kill -3 pid

    [junit] 2016-06-20 02:53:45
    [junit] Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.91-b14 mixed mode):
    [junit] 
    [junit] "File Watcher" #11 prio=5 os_prio=0 tid=0x00007f3e1003c000 nid=0x5c7b waiting on condition [0x00007f3e234f2000]
    [junit]    java.lang.Thread.State: WAITING (parking)
    [junit] 	at sun.misc.Unsafe.park(Native Method)
    [junit] 	- parking to wait for  <0x00000006c5333428> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    [junit] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    [junit] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    [junit] 	at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:492)
    [junit] 	at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:680)
    [junit] 	at sun.nio.fs.AbstractWatchService.take(AbstractWatchService.java:118)
    [junit] 	at org.openstreetmap.josm.io.FileWatcher.processEvents(FileWatcher.java:119)
    [junit] 	at org.openstreetmap.josm.io.FileWatcher.access$000(FileWatcher.java:30)
    [junit] 	at org.openstreetmap.josm.io.FileWatcher$1.run(FileWatcher.java:47)
    [junit] 	at java.lang.Thread.run(Thread.java:745)
    [junit] 
    [junit] "TimerQueue" #19 daemon prio=5 os_prio=0 tid=0x00007f3e10032800 nid=0x5c79 waiting on condition [0x00007f3e236f4000]
    [junit]    java.lang.Thread.State: WAITING (parking)
    [junit] 	at sun.misc.Unsafe.park(Native Method)
    [junit] 	- parking to wait for  <0x00000006c5ca80e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    [junit] 	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    [junit] 	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    [junit] 	at java.util.concurrent.DelayQueue.take(DelayQueue.java:211)
    [junit] 	at javax.swing.TimerQueue.run(TimerQueue.java:171)
    [junit] 	at java.lang.Thread.run(Thread.java:745)
    [junit] 
    [junit] "Java2D Disposer" #14 daemon prio=10 os_prio=0 tid=0x00007f3e7c93b800 nid=0x5c74 in Object.wait() [0x00007f3e5028e000]
    [junit]    java.lang.Thread.State: WAITING (on object monitor)
    [junit] 	at java.lang.Object.wait(Native Method)
    [junit] 	- waiting on <0x00000006c527ad78> (a java.lang.ref.ReferenceQueue$Lock)
    [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    [junit] 	- locked <0x00000006c527ad78> (a java.lang.ref.ReferenceQueue$Lock)
    [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    [junit] 	at sun.java2d.Disposer.run(Disposer.java:148)
    [junit] 	at java.lang.Thread.run(Thread.java:745)
    [junit] 
    [junit] "Thread-1" #10 daemon prio=5 os_prio=0 tid=0x00007f3e7c62d800 nid=0x5c71 runnable [0x00007f3e65397000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 	at sun.nio.fs.LinuxWatchService.poll(Native Method)
    [junit] 	at sun.nio.fs.LinuxWatchService.access$600(LinuxWatchService.java:47)
    [junit] 	at sun.nio.fs.LinuxWatchService$Poller.run(LinuxWatchService.java:314)
    [junit] 	at java.lang.Thread.run(Thread.java:745)
    [junit] 
    [junit] "Service Thread" #9 daemon prio=9 os_prio=0 tid=0x00007f3e7c376000 nid=0x5c6f runnable [0x0000000000000000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 
    [junit] "C1 CompilerThread2" #8 daemon prio=9 os_prio=0 tid=0x00007f3e7c318800 nid=0x5c6e waiting on condition [0x0000000000000000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 
    [junit] "C2 CompilerThread1" #7 daemon prio=9 os_prio=0 tid=0x00007f3e7c3fc800 nid=0x5c6d waiting on condition [0x0000000000000000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 
    [junit] "C2 CompilerThread0" #6 daemon prio=9 os_prio=0 tid=0x00007f3e7c31b800 nid=0x5c6c waiting on condition [0x0000000000000000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 
    [junit] "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f3e7c181000 nid=0x5c6b waiting on condition [0x0000000000000000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 
    [junit] "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f3e7c14e000 nid=0x5c6a in Object.wait() [0x00007f3e6641b000]
    [junit]    java.lang.Thread.State: WAITING (on object monitor)
    [junit] 	at java.lang.Object.wait(Native Method)
    [junit] 	- waiting on <0x00000006c526db00> (a java.lang.ref.ReferenceQueue$Lock)
    [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    [junit] 	- locked <0x00000006c526db00> (a java.lang.ref.ReferenceQueue$Lock)
    [junit] 	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    [junit] 	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
    [junit] 
    [junit] "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f3e7c149800 nid=0x5c69 in Object.wait() [0x00007f3e6651c000]
    [junit]    java.lang.Thread.State: WAITING (on object monitor)
    [junit] 	at java.lang.Object.wait(Native Method)
    [junit] 	- waiting on <0x00000006c526db40> (a java.lang.ref.Reference$Lock)
    [junit] 	at java.lang.Object.wait(Object.java:502)
    [junit] 	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    [junit] 	- locked <0x00000006c526db40> (a java.lang.ref.Reference$Lock)
    [junit] 	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
    [junit] 
    [junit] "main" #1 prio=5 os_prio=0 tid=0x00007f3e7c00c800 nid=0x5c62 runnable [0x00007f3e83ef6000]
    [junit]    java.lang.Thread.State: RUNNABLE
    [junit] 	at org.openstreetmap.josm.actions.SelectByInternalPointActionTest.testNoDataSet(SelectByInternalPointActionTest.java:41)
    [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    [junit] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    [junit] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    [junit] 	at java.lang.reflect.Method.invoke(Method.java:498)
    [junit] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    [junit] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    [junit] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    [junit] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    [junit] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    [junit] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    [junit] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    [junit] 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    [junit] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    [junit] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    [junit] 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    [junit] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    [junit] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    [junit] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    [junit] 	at junit.framework.JUnit4TestAdapter.run(JUnit4TestAdapter.java:38)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:535)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:1182)
    [junit] 	at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:1004)
    [junit] 
    [junit] "VM Thread" os_prio=0 tid=0x00007f3e7c141800 nid=0x5c68 runnable 
    [junit] 
    [junit] "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f3e7c022000 nid=0x5c64 runnable 
    [junit] 
    [junit] "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f3e7c023800 nid=0x5c65 runnable 
    [junit] 
    [junit] "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f3e7c025800 nid=0x5c66 runnable 
    [junit] 
    [junit] "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f3e7c027000 nid=0x5c67 runnable 
    [junit] 
    [junit] "VM Periodic Task Thread" os_prio=0 tid=0x00007f3e7c3f3000 nid=0x5c70 waiting on condition 
    [junit] 
    [junit] JNI global references: 5719
    [junit] 
    [junit] Heap
    [junit]  PSYoungGen      total 268800K, used 209936K [0x000000076c600000, 0x000000077f800000, 0x00000007c0000000)
    [junit]   eden space 258048K, 77% used [0x000000076c600000,0x0000000778886480,0x000000077c200000)
    [junit]   from space 10752K, 99% used [0x000000077c200000,0x000000077cc7dbd0,0x000000077cc80000)
    [junit]   to   space 25088K, 0% used [0x000000077df80000,0x000000077df80000,0x000000077f800000)
    [junit]  ParOldGen       total 115712K, used 35493K [0x00000006c5200000, 0x00000006cc300000, 0x000000076c600000)
    [junit]   object space 115712K, 30% used [0x00000006c5200000,0x00000006c74a94f8,0x00000006cc300000)
    [junit]  Metaspace       used 49239K, capacity 50406K, committed 50560K, reserved 1093632K
    [junit]   class space    used 5861K, capacity 6257K, committed 6272K, reserved 1048576K
    [junit] 
    [junit] Running org.openstreetmap.josm.tools.template_engine.Batch-With-Multiple-Tests
    [junit] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0 sec
    [junit] Tests FAILED (crashed)

comment:8 Changed 3 years ago by michael2402

I could not reproduce the freeze.

Do you have logs of the previous tests - especially the ones adding layers?

I added a patch that does:

  • Use the layer manager cleanup code in JOSMFixture
  • Clean the test environment before a JOSMTestRule test is run
  • Convert SelectByInternalPointActionTest to use JOSMTestRule

Changed 3 years ago by michael2402

Attachment: patch-fix-12974-2.patch added

comment:9 Changed 3 years ago by Don-vip

In 10443/josm:

see #12974 - Unit tests hang (patch by michael2402) - gsoc-core

comment:10 Changed 3 years ago by Don-vip

Previous logs can be found on Jenkins (builds 10430 and before):
https://josm.openstreetmap.de/jenkins/job/JOSM/

The job was disabled today because of this problem, I'm goind to enable it to see if the fix is ok.

comment:11 Changed 3 years ago by Don-vip

Resolution: fixed
Status: reopenedclosed

It seems fixed, thank you! :)

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain team.
as The resolution will be set.
The resolution will be deleted.

Add Comment


E-mail address and name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.