Moving 400 ways takes more than 20 seconds (WAS: JOSM freezes moving 400 ways)

[skyper]

I select all ways in the osm-file and try to move them. JOSM freezes.

java -Xmx2048M -jar josm-latest.jar
Repository Root: http://josm.openstreetmap.de/svn
Build-Date: 2010-08-16 01:31:17
Last Changed Author: jttt
Revision: 3443
Repository UUID: 0c6e7542-c601-0410-84e7-c038aed88b3b
URL: http://josm.openstreetmap.de/svn/trunk
Last Changed Date: 2010-08-15 22:04:43 +0200 (Sun, 15 Aug 2010)
Last Changed Rev: 3443

loading plugin 'openstreetbugs' (version 22548)
loading plugin 'ColumbusCSV' (version 305)
loading plugin 'wmsplugin' (version 22581)
loading plugin 'public_transport' (version 22048)
Silent shortcut conflict: 'menu:Public Transport' moved by 'menu:Presets' to 'Alt+B'.
loading plugin 'RoadSigns' (version 22449)
loading plugin 'remotecontrol' (version 22479)
RemoteControl::Accepting connections on port 8111
loading plugin 'validator' (version 22550)
GET http://api.openstreetmap.org/api/capabilities... OK
Communications with http://api.openstreetmap.org/api established using protocol version 0.6.
GET http://api.openstreetmap.org/api/0.6/map?bbox=7.6194102,47.7571418,7.6194906,47.757282499999995
Aug 16, 2010 11:59:43 PM org.openstreetmap.josm.actions.downloadtasks.DownloadOsmTask$DownloadTask realRun
WARNING: Ignoring exception because download has been cancelled. Exception was: org.openstreetmap.josm.io.OsmTransferException: java.net.SocketException: Socket closed
GET http://api.openstreetmap.org/api/0.6/map?bbox=7.6194102,47.7571418,7.6194906,47.757282499999995
Silent shortcut conflict: 'properties:add' moved by 'menu:Public Transport' to 'Alt+C'.
Silent shortcut conflict: 'subwindow:conflict' moved by 'properties:add' to 'Alt+Shift+C'.
Silent shortcut conflict: 'view:openstreetbugs' moved by 'system:download_primitive' to 'Ctrl+Alt+O'.
Open file: /home/zoidberg/Downloads/plz-79.osm (1799043 bytes)
GET http://api.openstreetmap.org/api/0.6/relation/62587/full
GET http://api.openstreetmap.org/api/0.6/relation/233450/full
GET http://api.openstreetmap.org/api/0.6/relation/288604/full
2010-08-17 00:05:51
Full thread dump OpenJDK Client VM (14.0-b16 mixed mode, sharing):

"OpenStreetBugs download loop" prio=10 tid=0xb3e9f800 nid=0x843 waiting on condition [0xb2874000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at org.openstreetmap.josm.plugins.osb.OsbDownloadLoop.run(OsbDownloadLoop.java:94)

"Map Status Collector" daemon prio=10 tid=0xb3eedc00 nid=0x842 in Object.wait() [0xb21dc000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at org.openstreetmap.josm.gui.MapStatus$Collector.run(MapStatus.java:149)
	- locked <0x19f20168> (a org.openstreetmap.josm.gui.MapStatus$Collector)
	at java.lang.Thread.run(Thread.java:636)

"pool-1-thread-1" prio=10 tid=0xb3616400 nid=0x839 waiting on condition [0xb35ad000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x19111718> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:636)

"Timer-0" daemon prio=10 tid=0xb3e8b400 nid=0x830 in Object.wait() [0xb35fe000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:505)
	- locked <0x19a5db88> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:484)

"OSMJobThread 1" daemon prio=10 tid=0xb29b2800 nid=0x82e waiting on condition [0xb37a5000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x19a36c88> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)
	at org.openstreetmap.gui.jmapviewer.JobDispatcher$JobThread.executeJobs(JobDispatcher.java:111)
	at org.openstreetmap.gui.jmapviewer.JobDispatcher$JobThread.run(JobDispatcher.java:98)

"RemoteControl HTTP Server" daemon prio=10 tid=0xb34cd000 nid=0x82d runnable [0xb2ab1000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:358)
	at java.net.ServerSocket.implAccept(ServerSocket.java:470)
	at java.net.ServerSocket.accept(ServerSocket.java:438)
	at org.openstreetmap.josm.plugins.remotecontrol.HttpServer.run(HttpServer.java:51)

"TimerQueue" daemon prio=10 tid=0x09649c00 nid=0x82a waiting on condition [0xb2b02000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x194028f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
	at java.util.concurrent.DelayQueue.take(DelayQueue.java:189)
	at javax.swing.TimerQueue.run(TimerQueue.java:166)
	at java.lang.Thread.run(Thread.java:636)

"AWT-EventQueue-0" prio=10 tid=0xb3e85c00 nid=0x825 runnable [0xb37f6000]
   java.lang.Thread.State: RUNNABLE
	at java.util.ArrayList.size(ArrayList.java:197)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectionListModel.getSize(SelectionListDialog.java:551)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectionListModel.getSelected(SelectionListDialog.java:562)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectAction.updateEnabledState(SelectionListDialog.java:338)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectAction.valueChanged(SelectionListDialog.java:342)
	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:184)
	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:164)
	at javax.swing.DefaultListSelectionModel.fireValueChanged(DefaultListSelectionModel.java:211)
	at javax.swing.DefaultListSelectionModel.changeSelection(DefaultListSelectionModel.java:405)
	at javax.swing.DefaultListSelectionModel.changeSelection(DefaultListSelectionModel.java:415)
	at javax.swing.DefaultListSelectionModel.addSelectionInterval(DefaultListSelectionModel.java:518)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectionListModel.setSelected(SelectionListDialog.java:591)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectionListModel.update(SelectionListDialog.java:636)
	at org.openstreetmap.josm.gui.dialogs.SelectionListDialog$SelectionListModel.nodeMoved(SelectionListDialog.java:700)
	at org.openstreetmap.josm.data.osm.event.NodeMovedEvent.fire(NodeMovedEvent.java:22)
	at org.openstreetmap.josm.data.osm.event.DatasetEventManager.fireEvents(DatasetEventManager.java:109)
	at org.openstreetmap.josm.data.osm.event.DatasetEventManager.access$200(DatasetEventManager.java:27)
	at org.openstreetmap.josm.data.osm.event.DatasetEventManager$1.run(DatasetEventManager.java:139)
	at java.awt.event.InvocationEvent.dispatch(InvocationEvent.java:226)
	at java.awt.EventQueue.dispatchEvent(EventQueue.java:602)
	at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:275)
	at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:200)
	at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:190)
	at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:185)
	at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:177)
	at java.awt.EventDispatchThread.run(EventDispatchThread.java:138)

"AWT-Shutdown" prio=10 tid=0xb3e85400 nid=0x824 in Object.wait() [0xb3847000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:281)
	- locked <0x19312d38> (a java.lang.Object)
	at java.lang.Thread.run(Thread.java:636)

"AWT-XAWT" daemon prio=10 tid=0xb3e71c00 nid=0x81f runnable [0xb3898000]
   java.lang.Thread.State: RUNNABLE
	at sun.awt.X11.XToolkit.waitForEvents(Native Method)
	at sun.awt.X11.XToolkit.run(XToolkit.java:548)
	at sun.awt.X11.XToolkit.run(XToolkit.java:523)
	at java.lang.Thread.run(Thread.java:636)

"Java2D Disposer" daemon prio=10 tid=0xb3e44c00 nid=0x81e in Object.wait() [0xb39bc000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
	- locked <0x1914de88> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
	at sun.java2d.Disposer.run(Disposer.java:143)
	at java.lang.Thread.run(Thread.java:636)

"Low Memory Detector" daemon prio=10 tid=0xb3e00800 nid=0x81c runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x093d0400 nid=0x81b waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x093ce800 nid=0x81a waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x093c6800 nid=0x819 in Object.wait() [0xb41cd000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
	- locked <0x18e7a988> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x093c5000 nid=0x818 in Object.wait() [0xb421e000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x18e7aa10> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x09364000 nid=0x816 in Object.wait() [0xb6d8d000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.awt.Dialog.show(Dialog.java:1137)
	- locked <0x1911bbd8> (a java.awt.Component$AWTTreeLock)
	at java.awt.Component.show(Component.java:1464)
	at java.awt.Component.setVisible(Component.java:1416)
	at java.awt.Window.setVisible(Window.java:842)
	at java.awt.Dialog.setVisible(Dialog.java:1011)
	at org.openstreetmap.josm.gui.ExtendedDialog.setVisible(ExtendedDialog.java:448)
	at org.openstreetmap.josm.gui.ExtendedDialog.showDialog(ExtendedDialog.java:254)
	at org.openstreetmap.josm.gui.MainApplication.main(MainApplication.java:260)

"VM Thread" prio=10 tid=0x093c3400 nid=0x817 runnable 

"VM Periodic Task Thread" prio=10 tid=0xb3e02800 nid=0x81d waiting on condition 

JNI global references: 2605

Heap
 def new generation   total 3776K, used 1080K [0x0f070000, 0x0f480000, 0x18df0000)
  eden space 3392K,  31% used [0x0f070000, 0x0f17a448, 0x0f3c0000)
  from space 384K,   4% used [0x0f420000, 0x0f423f20, 0x0f480000)
  to   space 384K,   0% used [0x0f3c0000, 0x0f3c0000, 0x0f420000)
 tenured generation   total 49552K, used 41369K [0x18df0000, 0x1be54000, 0x8f070000)
   the space 49552K,  83% used [0x18df0000, 0x1b656488, 0x1b656600, 0x1be54000)
 compacting perm gen  total 12288K, used 9214K [0x8f070000, 0x8fc70000, 0x93070000)
   the space 12288K,  74% used [0x8f070000, 0x8f96fa80, 0x8f96fc00, 0x8fc70000)
    ro space 8192K,  89% used [0x93070000, 0x937a0708, 0x937a0800, 0x93870000)
    rw space 12288K,  59% used [0x93870000, 0x93f9edd8, 0x93f9ee00, 0x94470000)

cu skyper

debian-testing, openjdk, lxde

[skyper]

osm file

[skyper]

The NPE is gone but I noticed that moving all ways takes way too long.

Rendering is not the issue. The problem lies in the warning of moving 20+ objects. Seems to me the routine does not stop counting with the 21st objects but counts all.

On a slow machine you have to wait 20+ seconds for the warning while rendering takes just 1 sec.

Repository Root: http://josm.openstreetmap.de/svn
Build-Date: 2012-02-20 11:59:50
Last Changed Author: xeen
Revision: 5004
Repository UUID: 0c6e7542-c601-0410-84e7-c038aed88b3b
URL: http://josm.openstreetmap.de/svn/trunk
Last Changed Date: 2012-02-20 12:32:21 +0100 (Mon, 20 Feb 2012)
Last Changed Rev: 5004

Identification: JOSM/1.5 (5004 en)
Memory Usage: 34 MB / 508 MB (4 MB allocated, but free)
Java version: 1.6.0_18, Sun Microsystems Inc., OpenJDK Client VM
Operating system: Linux
Dataset consistency test: No problems found

[JB]

I did some profiling and believe I've determined the cause of the slowness. When you move a selection, a NodeMovedEvent is fired for every node in the selection. Each of these NodeMovedEvents causes the SelectionListDialog to update.

If you're moving just a single node, this makes sense; when you move a node, you want it to update the SelectionListDialog right away so you can see the coordinates changing. But if you're moving thousands of nodes, this is silly. Every single node triggers SelectionListDialog$SelectionListModel.update, which can take a few milliseconds to run. If you're moving 8,000 nodes, this adds up fast. These updates are totally redundant; calling SelectionListDialog$SelectionListModel.update just once would accomplish the same thing as calling it 8,000 times in a row. There's no reason, as far as I can tell, for every node in the selection to update the SelectionListDialog.

If you want to confirm for yourself that updating the SelectionListDialog is responsible for the performance, you can comment out the contents of the nodeMoved method in SelectionListDialog.java and watch the performance improve dramatically.

This is my first time ever looking at JOSM's source code, so I'm not sure what the best way to fix this is. If someone more experienced with the code base has an idea of the best approach to take, I'd be willing to take a stab at developing a fix.

[stoecker]

The Dataset has function to disable/enable notifications. Usually these should be used before every batch operations, but usually this gets overlooked. So fix should be simply adding a call to these before and after the large operation - then only a single notification is sent.

[akks]

I tried to insert beginUpdate/endUpdate when moving nodes, as adviced (see code in #7888).

NodeMoveEvents were eliminated, small number DataChange appear instead of them. Performance increase, but I can not say is is really fast now - please check this build: ​http://dl.dropbox.com/u/63393258/josm-custom.jar

[stoecker]

I would checkin the fix anyway even if it does not fully solve the issue.

[akks]

In 5370/josm:

see #5341: faster nodes moving (by JB) beginUpdate/endUpdate) + big refactoring of SelectAction.java
behavior of Select tool should NOT change (just more structured code), see #7888

[akks]

Oops, another typo in commit comment. Sorry.

@JB: Thank you for detailed description of a problem! Please continue you observations, you can send a patch or ideas at any time.

[JB]

Nice! The improvement is significant. To quantify it, I carried out a performance test with and without akks's changes, measuring the time elapsed from the moment I finish dragging my mouse to the moment the confirmation pop-up appears. On my laptop, the elapsed time (averaged over ten runs) was 4975 milliseconds in the old version and 3 milliseconds with akks's changes; that is better than a thousandfold improvement in response time! :-) Of course, dragging around such a large selection is still sluggish due to the rendering time, but I would say that the problem as skyper stated it has been fixed.

By the way, I noticed that "nudging" the nodes with Shift+Arrow results in the same problem. I'm attaching a patch that attempts to fix it, copying what akks did. It's quite simple, just adding calls to beginUpdate and endUpdate, and it seems to work OK, but someone knowledgeable should make sure I put the calls in the right place.

[stoecker]

In r5377 :-)

[akks]

Thank you!

By the way, why "see #7888" did not add automatic comment here?

P.S. Oops - my mistake, ticket number is #5341 . I'll pay more attention to comments next times...