Very slow drawing of new ways (r2270)

[bilbo]

I noticed that when I downloaded one area from OSM, then editing (drawing new ways) is unusually slow. First I suspected WMS, but even if there is only layer with data and nothing else (WMS, waypoints ...) is loaded, drawing new ways is very slow, when I click some points, I have to wait sometimes several seconds before the new way is actually drawn.

Perhaps some bug in quadbuckets code?

I am attaching the file with saved area that I was trying to edit.

[bilbo]

OSM data that is slow to edit

[bilbo]

Some experiments with profiler (running josm with this data loaded, then I start drawing some new lines) show 45% of CPU time spent in QuadBuckets$QuadBucketsIterator, methods with highest accumulated CPU time count (including called submethods) are these:

DrawAction.mouseClicked(MouseEvent)			283631 ms
DataSet.getSelected(Collection)				183251 ms
DataSet.fireSelectionChanged(Collection)		178604 ms
DataSet.getSelected()					140242 ms
DrawAction.selectionChanged(Collection)			140089 ms
QuadBuckets$QuadBucketIterator.next()			111771 ms
DrawAction.computeHelperLine()				109628 ms
QuadBuckets$QuadBucketIterator.peek()			105605 ms
QuadBuckets$QuadBucketIterator.hasNext()		 92950 ms
NavigatableComponent.getNearestWaySegments(Point)	 85030 ms
NavigatableComponent.getNearestNode(Point)		 81545 ms

[bilbo]

I tried another profiler and this time I measured only the time while I was drawing things

Considering I clicked only about 20 times to create 20nodes way, some methods like
org.openstreetmap.josm.data.osm.DataSet.setSelected() and org.openstreetmap.josm.data.UndoRedoHandler.add()
seem to eat quite a lot more CPU time than you would expect.

[187401ms] org.openstreetmap.josm.actions.mapmode.DrawAction.mouseClicked(java.awt.event.MouseEvent)
	[ 5%;   9537ms] org.openstreetmap.josm.gui.NavigatableComponent.getNearestWaySegments()
	[ 5%;   9831ms] org.openstreetmap.josm.actions.mapmode.DrawAction.redrawIfRequired()
		[ 5%;   1582ms] org.openstreetmap.josm.actions.mapmode.MapMode.updateStatusLine()
	[ 5%;  10141ms] org.openstreetmap.josm.actions.mapmode.DrawAction.tryAgain()
	[ 6%;  11026ms] org.openstreetmap.josm.actions.mapmode.DrawAction.computeHelperLine()
	[19%;  36436ms] org.openstreetmap.josm.data.UndoRedoHandler.add()
		[19%;   7079ms] org.openstreetmap.josm.data.UndoRedoHandler.afterAdd()
	[25%;  47388ms] org.openstreetmap.josm.data.osm.DataSet.setSelected()
[ 31299ms] org.openstreetmap.josm.gui.MapStatus$Collector.statusBarElementUpdate(org.openstreetmap.josm.gui.MapStatus$MouseState)
	[100%;  31230ms] org.openstreetmap.josm.gui.NavigatableComponent.getNearest()
[ 13845ms] org.openstreetmap.josm.gui.MapView.paint(java.awt.Graphics)
	[98%;  13521ms] org.openstreetmap.josm.gui.layer.OsmDataLayer.paint()
[ 12457ms] org.openstreetmap.josm.gui.MainApplication$2.run()
	[100%;  12457ms] org.openstreetmap.josm.Main.postConstructorProcessCmdLine()
[  2990ms] org.openstreetmap.josm.actions.mapmode.DrawAction.mouseMoved(java.awt.event.MouseEvent)
	[27%;    806ms] org.openstreetmap.josm.actions.mapmode.DrawAction.addHighlighting()
[  2828ms] org.openstreetmap.josm.gui.MultiSplitPane.paintChildren(java.awt.Graphics)
	[97%;   2750ms] org.openstreetmap.josm.gui.dialogs.LayerListDialog$LayerListCellRenderer.getListCellRendererComponent()
[  1446ms] org.openstreetmap.josm.gui.SelectionManager.mouseReleased(java.awt.event.MouseEvent)
	[100%;   1446ms] org.openstreetmap.josm.actions.mapmode.SelectAction.selectionEnded()
[  1437ms] org.openstreetmap.josm.actions.mapmode.DrawAction.eventDispatched(java.awt.AWTEvent)
	[29%;    419ms] org.openstreetmap.josm.actions.mapmode.DrawAction.addHighlighting()
[  1164ms] org.openstreetmap.josm.actions.mapmode.SelectAction.mousePressed(java.awt.event.MouseEvent)
	[100%;   1160ms] org.openstreetmap.josm.actions.mapmode.SelectAction.getNearestCollectionVirtual()
[  1043ms] org.openstreetmap.josm.actions.UnselectAllAction.actionPerformed(java.awt.event.ActionEvent)
[   961ms] org.openstreetmap.josm.gui.MapView$1.componentResized(java.awt.event.ComponentEvent)
[   541ms] org.openstreetmap.josm.gui.MapStatus$2.eventDispatched(java.awt.AWTEvent)
[   419ms] org.openstreetmap.josm.actions.mapmode.MapMode.actionPerformed(java.awt.event.ActionEvent)
[   396ms] org.openstreetmap.josm.actions.mapmode.SelectAction.mouseReleased(java.awt.event.MouseEvent)
[    62ms] org.openstreetmap.josm.gui.OsmPrimitivRenderer.getListCellRendererComponent(javax.swing.JList,java.lang.Object,int,boolean,boolean)
[    53ms] org.openstreetmap.josm.gui.NavigatableComponent.getCenter()
[    32ms] org.openstreetmap.josm.gui.MultiSplitLayout.layoutContainer(java.awt.Container)
[     7ms] org.openstreetmap.josm.gui.MapStatus$ImageLabel.getPreferredSize()
[     4ms] org.openstreetmap.josm.actions.mapmode.SelectAction.mouseMoved(java.awt.event.MouseEvent)
[     4ms] org.openstreetmap.josm.actions.mapmode.DrawAction$1.run()
[     3ms] org.openstreetmap.josm.gui.MultiSplitLayout.preferredLayoutSize(java.awt.Container)
[     3ms] org.openstreetmap.josm.gui.MultiSplitLayout.minimumLayoutSize(java.awt.Container)

[bilbo]

One of the causes would be probably src/org/openstreetmap/josm/data/osm/Dataset.java - in all variants of setSelected, there is code:

        clearSelection(nodes);
        clearSelection(ways);
        clearSelection(relations);

which will iterate through entire dataset to unmark all selections.

Calling getSelected will basically also loop through entire dataset.

I tried also one of older JOSM versions (r2255) with this data and the speed was OK. I guess some change between 2255 and 2270 brought in this regression.

[bilbo]

Tried bisecting and I found out that r2262 is running fine, and r2263 sufers with this slooowness.

So the cause is in r2263: applied #3671 - patch by Dave Hansen - performance fixes of data storage

[hansendc]

Thanks for the excellent bug report. I've been seeing some of the exact same issues. It does seem that iteration through a tree is significantly slower than the iteration through the plain old lists. I can probably improve the iteration speed, but the correct way to fix this is probably to fix all of the iterators. I'll look at your data set and see if anything looks easy to fix.

I actually have patches that fix the selection code. They've been posted to trac and I'm waiting to see them applied.

This code:

NavigatableComponent.getNearestWaySegments(Point) 85030 ms
NavigatableComponent.getNearestNode(Point) 81545 ms

is pretty bad as well for iterating over the whole data set. It is a great candidate for using the QuadBuckets search mechanisms. But, we need to be able to tell the QuadBuckets code when ways and nodes move before we can use it widely. I have patches to do the searches, but they'll be buggy any time a node or any node in a way is moved.

I'll accept this bug and hold on to it until we get some of this stuff implemented.

[stoecker]

You talk about #3696? Please see Gubaers comment there.

Regarding update mechanism - Can't you hook into UndoRedoHandler? All changes must go through this handler. The only excption should be loading/ and up-/downloads.

[hansendc]

OK, here's a big patch set to hopefully speed up mouse clicks. I'll attach one big patch as well as a broken-out set in a tarball. This is lightly tested, but it really speed up my mouse clicks.

[hansendc]

bilbo, I'm also curious what profilers you are using. Your output looks much nicer than what I'm using (hprof).

[bilbo]

First I tried JRat, but it was not very good, so the second output is from profiler4j 1.0-beta2

[stoecker]

Fixed?

[bilbo]

In r2437 the slowness is fixed (drawing seems to be reasonably fast, no more large delay after every click)

I have not run benchmarks to find out if it is faster or slower than before, but it is fast enough in r2437, so I don't have any problems with it anymore.