[GraphHopper] GraphHopper init slowed down with 6c8f0549

Tue Dec 3 15:04:14 UTC 2013

I'm not sure why this is, but after updating to the latest master, I
have to wait ~18 minutes for a pretty small pbf
(koeln-regbez-latest.osm.pbf):

2013-12-03 14:31:52,384 [main] INFO  GraphHopperConfigFactory - Using
{location=/Users/tfnico/Downloads/graphhopper/workdir,
osmFile=/Users/tfnico/Downloads/graphhopper/koeln-regbez-latest.osm.pbf}
2013-12-03 14:31:52,529 [main] INFO  GraphHopper - version
0.3|2013-12-03T14:20 (2,3,2,2,2)
2013-12-03 14:31:52,531 [main] INFO  GraphHopper - graph
LevelGraphStorage|car|RAM_STORE|,,,,, details:edges:0(0), nodes:0(0),
name: - (0), geo:4(0),
bounds:1.7976931348623157E308,-1.7976931348623157E308,1.7976931348623157E308,-1.7976931348623157E308
2013-12-03 14:31:52,531 [main] INFO  GraphHopper - start creating
graph from /Users/tfnico/Downloads/graphhopper/koeln-regbez-latest.osm.pbf
2013-12-03 14:31:52,547 [main] INFO  GraphHopper - using
LevelGraphStorage|car|RAM_STORE|,,,,, memory:totalMB:81, usedMB:12
2013-12-03 14:32:01,231 [main] INFO  OSMReader - creating graph. Found
nodes (pillar+tower):1 185 912, totalMB:1030, usedMB:1015
2013-12-03 14:32:04,868 [main] INFO  OSMReader - 5 000 000, locs:1 055
690 (0) totalMB:1778, usedMB:1200
2013-12-03 14:32:05,477 [main] INFO  OSMReader - 6 411 458, now parsing ways
2013-12-03 14:32:10,275 [main] INFO  OSMReader - finished way
processing. nodes: 311940, osmIdMap.size:1192844, osmIdMap:18MB,
osmIdMap.toString:Height:3, entries:9072 totalMB:1778, usedMB:984
2013-12-03 14:32:10,276 [main] INFO  OSMReader - time(pass1): 8 pass2:
9 total:17
2013-12-03 14:32:10,294 [main] INFO  GraphHopper - start finding
subnetworks, totalMB:1778, usedMB:968
2013-12-03 14:32:10,525 [main] INFO  PrepareRoutingSubnetworks -
optimize to remove subnetworks (6744), zero-degree-nodes (0),
maxEdges/node (8)
2013-12-03 14:32:10,886 [main] INFO  GraphHopper - edges: 385426,
nodes 294964, there were 6744 subnetworks. removed them => 16976 less
nodes. Remaining subnetworks:1
2013-12-03 14:32:10,887 [main] INFO  GraphHopper - optimizing ...
(totalMB:1778, usedMB:595)
2013-12-03 14:32:10,887 [main] INFO  GraphHopper - finished optimize
(totalMB:1778, usedMB:595)
2013-12-03 14:32:10,965 [main] INFO  GraphHopper - calling
prepare.doWork ... (totalMB:1778, usedMB:526)
[wait for 18 minutes or so]

Whereas before, things would start a bit smoother:

2013-12-03 14:11:50,400 [main] INFO  PrepareRoutingSubnetworks -
optimize to remove subnetworks (6744), zero-degree-nodes (0),
maxEdges/node (8)
2013-12-03 14:11:50,695 [main] INFO  GraphHopper - edges: 385426,
nodes 294964, there were 6744 subnetworks. removed them => 16976 less
nodes. Remaining subnetworks:1
2013-12-03 14:11:50,695 [main] INFO  GraphHopper - optimizing ...
(totalMB:1294, usedMB:308)
2013-12-03 14:11:50,695 [main] INFO  GraphHopper - finished optimize
(totalMB:1294, usedMB:308)
2013-12-03 14:11:50,701 [main] INFO  GraphHopper - calling
prepare.doWork ... (totalMB:1294, usedMB:306)
2013-12-03 14:11:54,458 [main] INFO  PrepareContractionHierarchies -
1, nodes: 294 964, shortcuts:0, dijkstras:1 225 646, t(dijk):3,
t(period):0, t(lazy):0, t(neighbor):0, meanDegree:1, totalMB:1294,
usedMB:241

So, jump from 4 seconds to 18 minutes.

Some random thread-dumps of what's going on while waiting:

"main" prio=5 tid=7f9362001000 nid=0x102e40000 runnable [102e3d000]
   java.lang.Thread.State: RUNNABLE
at com.graphhopper.routing.util.DefaultEdgeFilter.accept(DefaultEdgeFilter.java:51)
at com.graphhopper.storage.GraphHopperStorage$EdgeIterable.next(GraphHopperStorage.java:710)
at com.graphhopper.routing.DijkstraOneToMany.findEndNode(DijkstraOneToMany.java:150)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.findShortcuts(PrepareContractionHierarchies.java:583)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.calculatePriority(PrepareContractionHierarchies.java:505)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.prepareNodes(PrepareContractionHierarchies.java:238)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:200)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:57)
at com.graphhopper.GraphHopper.prepare(GraphHopper.java:720)
at com.graphhopper.GraphHopper.postProcessing(GraphHopper.java:536)
at com.graphhopper.GraphHopper.process(GraphHopper.java:444)
at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:417)

Another a few seconds later:

"main" prio=5 tid=7f9362001000 nid=0x102e40000 runnable [102e3d000]
   java.lang.Thread.State: RUNNABLE
at com.graphhopper.coll.IntDoubleBinHeap.update_(IntDoubleBinHeap.java:184)
at com.graphhopper.routing.DijkstraOneToMany.findEndNode(DijkstraOneToMany.java:172)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.findShortcuts(PrepareContractionHierarchies.java:583)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.calculatePriority(PrepareContractionHierarchies.java:505)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.prepareNodes(PrepareContractionHierarchies.java:238)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:200)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:57)
at com.graphhopper.GraphHopper.prepare(GraphHopper.java:720)
at com.graphhopper.GraphHopper.postProcessing(GraphHopper.java:536)
at com.graphhopper.GraphHopper.process(GraphHopper.java:444)
at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:417)

Another a few seconds later:

"main" prio=5 tid=7f9362001000 nid=0x102e40000 runnable [102e3d000]
   java.lang.Thread.State: RUNNABLE
at com.graphhopper.coll.IntDoubleBinHeap.poll_element(IntDoubleBinHeap.java:111)
at com.graphhopper.routing.DijkstraOneToMany.findEndNode(DijkstraOneToMany.java:186)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.findShortcuts(PrepareContractionHierarchies.java:583)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.calculatePriority(PrepareContractionHierarchies.java:505)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.prepareNodes(PrepareContractionHierarchies.java:238)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:200)
at com.graphhopper.routing.ch.PrepareContractionHierarchies.doWork(PrepareContractionHierarchies.java:57)
at com.graphhopper.GraphHopper.prepare(GraphHopper.java:720)
at com.graphhopper.GraphHopper.postProcessing(GraphHopper.java:536)
at com.graphhopper.GraphHopper.process(GraphHopper.java:444)
at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:417)

I manually bisected my way to the guilty commit (in subject), and ran
the test before/after about 10 times, so I'm kind of certain that the
problem was introduced at that point (but could always be wrong).

Here's the commit on GitHub, for easy reference:

https://github.com/graphhopper/graphhopper/commit/6c8f05490d05211e05d27a7757fdaea229ad57ee

I tried updating to the latest master at da3a36f2cfb8f - but the
problem still occurs.