Modify ↓

Opened 8 years ago

Closed 8 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 8 years ago.
patch-fix-12974-2.patch​ (8.9 KB ) - added by michael2402 8 years ago.

Download all attachments as: .zip

Change History (13)

comment:1 by michael2402, 8 years ago

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 by michael2402, 8 years ago

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

comment:3 by Don-vip, 8 years ago

wrong patch :)

by michael2402, 8 years ago

Attachment: patch-fix-12974.patch​ added

comment:4 by michael2402, 8 years ago

Thanks, this is the right one...

comment:5 by Don-vip, 8 years ago

Resolution: → fixed
Status: new → closed

In 10400/josm:

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

comment:6 by Don-vip, 8 years ago

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

comment:7 by Don-vip, 8 years ago

Resolution: fixed
Status: closed → reopened

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 by michael2402, 8 years ago

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

by michael2402, 8 years ago

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

comment:9 by Don-vip, 8 years ago

In 10443/josm:

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

comment:10 by Don-vip, 8 years ago

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 by Don-vip, 8 years ago

Resolution: → fixed
Status: reopened → closed

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. Next status will be 'reopened'.

Add Comment
E-mail address and name can be saved in the Preferences .
Attachments ↑ Description ↑
 
Note: See TracTickets for help on using tickets.