Multiple CHWeightings per FlagEncoder

boldtrn · January 12, 2016, 9:32am

Hi,

we just merged my PR that allowed to use multiple CHWeightings per FlagEncoder. I’ve use this with two weightings in production for about 2 weeks now. I just added a third weighting which increased the import time from about 1.5hrs to more than 6hrs. I just checked the import of a single CHWeighting takes 30mins (even with my new weighting). With 2 weightings 1.5hrs. With 3, more than 6hrs. This seems weird.

Any idea how this could be solved or a hint what to do about this?
I expected that the time would grow more or less linear.

Best,
Robin

karussell · January 12, 2016, 5:53pm

30 minutes for which region, Germany? This would be relative slow but your weighting is rather expensive to calculate? Are you executing the preparations in parallel and ensured enough RAM?

Can you look into the timings again and confirm that the CH preparation takes this long or is it before or afterwards? E.g. in the subnetwork search like we had a similar issue here: https://github.com/graphhopper/graphhopper/issues/520

If it is really the CH maybe related to this old here? https://github.com/graphhopper/graphhopper/issues/128

boldtrn · January 13, 2016, 8:08am

Hi Peter,

I currently run the DACH area (approx. 25-30% bigger than only germany) and I have a rather weak cpu (2.3GHZ). The Import runs on only one core (can it run on two cores and does it actually improve?) I use 3.5 gb of RAM (should be enough? The .pbf file is about 3.3 gb)). Here is the shortened log from tonight:

» 13 Jan 2016 00:11:31.847 Wed Jan 13 00:11:31 +0100 2016, (OSMReader.java:193) INFO : 5 000 000 (preprocess), osmIdMap:32 758 659 (427MB) totalMB:3435, usedMB:1068
<Shortened>
» 13 Jan 2016 00:12:45.915 Wed Jan 13 00:12:45 +0100 2016, (OSMReader.java:210) INFO : 600 000 (preprocess), osmWayMap:0 totalMB:3397, usedMB:2697
» 13 Jan 2016 00:12:46.048 Wed Jan 13 00:12:45 +0100 2016, (OSMReader.java:284) INFO : creating graph. Found nodes (pillar+tower):40 009 669, totalMB:3397, usedMB:3012
» 13 Jan 2016 00:12:46.125 Wed Jan 13 00:12:45 +0100 2016, (SRTMProvider.java:344) INFO : SRTM Elevation ... BlaBla
» 13 Jan 2016 00:14:52.961 Wed Jan 13 00:14:52 +0100 2016, (OSMReader.java:326) INFO : 100 000 000, locs:22 497 534 (0) totalMB:3456, usedMB:1638
<Shortened>
» 13 Jan 2016 00:22:09.197 Wed Jan 13 00:22:08 +0100 2016, (OSMReader.java:1044) INFO : finished way processing. nodes: 9612670, osmIdMap.size:40133938, osmIdMap:473MB, nodeFlagsMap.size:124269, relFlagsMap.size:0, zeroCounter:123076 totalMB:3470, usedMB:2891
» 13 Jan 2016 00:22:10.285 Wed Jan 13 00:22:09 +0100 2016, (OSMReader.java:158) INFO : time(pass1): 340 pass2: 564 total:905
» 13 Jan 2016 00:22:10.308 Wed Jan 13 00:22:09 +0100 2016, (GraphHopper.java:1415) INFO : start finding subnetworks, totalMB:3469, usedMB:1327
» 13 Jan 2016 00:22:17.619 Wed Jan 13 00:22:16 +0100 2016, (PrepareRoutingSubnetworks.java:85) INFO : 217256 subnetworks found for motorcycle, totalMB:3469, usedMB:1689
» 13 Jan 2016 00:22:19.430 Wed Jan 13 00:22:18 +0100 2016, (PrepareRoutingSubnetworks.java:90) INFO : optimize to remove subnetworks (217256), unvisited-dead-end-nodes (0), maxEdges/node (13)
» 13 Jan 2016 00:23:32.264 Wed Jan 13 00:23:31 +0100 2016, (GraphHopper.java:1418) INFO : edges: 11314739, nodes 9051466, there were 217256 subnetworks. removed them => 561204 less nodes
» 13 Jan 2016 00:23:52.048 Wed Jan 13 00:23:51 +0100 2016, (LocationIndexTree.java:331) INFO : location index created in 19.853432s, size:10 131 826, leafs:2 110 280, precision:300, depth:5, checksum:9051466, entries:[64, 64, 64, 16, 4], entriesPerLeaf:4.801176
» 13 Jan 2016 00:23:52.452 Wed Jan 13 00:23:51 +0100 2016, (GraphHopper.java:1362) INFO : 1/3 calling prepare.doWork for curvature|motorcycle ... (totalMB:3412, usedMB:1937)
» 13 Jan 2016 00:23:52.502 Wed Jan 13 00:23:51 +0100 2016, (GraphHopper.java:1362) INFO : 2/3 calling prepare.doWork for curvaturebooster|motorcycle ... (totalMB:3412, usedMB:1937)
» 13 Jan 2016 00:23:52.525 Wed Jan 13 00:23:51 +0100 2016, (GraphHopper.java:1362) INFO : 3/3 calling prepare.doWork for curvaturefastest|motorcycle ... (totalMB:3412, usedMB:1946)
» 13 Jan 2016 00:24:53.207 Wed Jan 13 00:24:52 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 0, updates:0, nodes: 9 051 466, shortcuts:0, dijkstras:35 080 294, t(dijk):25.19, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:138MB, totalMB:2805, usedMB:1801
» 13 Jan 2016 00:25:03.155 Wed Jan 13 00:25:02 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 1 810 280, updates:0, nodes: 7 241 186, shortcuts:975, dijkstras:35 800 093, t(dijk):29.53, t(period):0.0, t(lazy):0.0, t(neighbor):6.69, meanDegree:1, algo:138MB, totalMB:2805, usedMB:1903
» 13 Jan 2016 00:29:14.810 Wed Jan 13 00:29:14 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 3 620 560, updates:1, nodes: 5 430 906, shortcuts:798 219, dijkstras:67 696 812, t(dijk):238.63, t(period):199.28, t(lazy):0.0, t(neighbor):28.19, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2288
» 13 Jan 2016 00:33:18.193 Wed Jan 13 00:33:17 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 5 430 840, updates:2, nodes: 3 620 626, shortcuts:2 108 594, dijkstras:93 549 730, t(dijk):439.1, t(period):366.54, t(lazy):0.0, t(neighbor):60.57, meanDegree:1, algo:138MB, totalMB:3111, usedMB:1827
» 13 Jan 2016 00:37:41.785 Wed Jan 13 00:37:41 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 7 241 120, updates:3, nodes: 1 810 346, shortcuts:3 749 573, dijkstras:115 620 558, t(dijk):661.1, t(period):526.24, t(lazy):0.0, t(neighbor):104.15, meanDegree:2, algo:138MB, totalMB:3111, usedMB:1994
» 13 Jan 2016 00:43:43.843 Wed Jan 13 00:43:43 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 276 203, shortcuts:5 682 169, dijkstras:143 145 301, t(dijk):975.67, t(period):646.94, t(lazy):80.33, t(neighbor):185.45, meanDegree:3, algo:138MB, totalMB:3145, usedMB:2048
» 13 Jan 2016 00:49:27.191 Wed Jan 13 00:49:26 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:1534, new shortcuts: 6 460 754, prepare|curvature, motorcycle, dijkstras:165498373, t(dijk):1295.82, t(period):690.27, t(lazy):183.08, t(neighbor):339.52, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3145, usedMB:2280
» 13 Jan 2016 00:50:45.005 Wed Jan 13 00:50:44 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 0, updates:0, nodes: 9 051 466, shortcuts:0, dijkstras:35 080 294, t(dijk):31.92, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:138MB, totalMB:3068, usedMB:1996
» 13 Jan 2016 00:51:03.479 Wed Jan 13 00:51:02 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 1 810 280, updates:0, nodes: 7 241 186, shortcuts:975, dijkstras:35 790 622, t(dijk):43.99, t(period):0.0, t(lazy):0.0, t(neighbor):14.81, meanDegree:1, algo:138MB, totalMB:3068, usedMB:2098
» 13 Jan 2016 01:06:19.582 Wed Jan 13 01:06:18 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 3 620 560, updates:1, nodes: 5 430 906, shortcuts:855 921, dijkstras:67 593 629, t(dijk):896.15, t(period):766.67, t(lazy):0.0, t(neighbor):79.67, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2605
» 13 Jan 2016 01:30:18.854 Wed Jan 13 01:30:18 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 5 430 840, updates:2, nodes: 3 620 626, shortcuts:2 257 752, dijkstras:93 697 905, t(dijk):2263.54, t(period):1913.98, t(lazy):0.0, t(neighbor):208.24, meanDegree:1, algo:138MB, totalMB:3111, usedMB:2080
» 13 Jan 2016 01:47:49.716 Wed Jan 13 01:47:48 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 7 241 120, updates:3, nodes: 1 810 346, shortcuts:4 099 327, dijkstras:116 389 959, t(dijk):3247.52, t(period):2493.4, t(lazy):0.0, t(neighbor):425.85, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2273
» 13 Jan 2016 02:47:36.206 Wed Jan 13 02:47:35 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 397 669, shortcuts:6 564 311, dijkstras:146 853 590, t(dijk):6721.93, t(period):3394.38, t(lazy):1080.24, t(neighbor):1240.13, meanDegree:3, algo:138MB, totalMB:3111, usedMB:2046

<This GAP is Probably most Interesting, but there are no Logs here>

» 13 Jan 2016 06:31:48.657 Wed Jan 13 06:31:47 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:20541, new shortcuts: 8 009 827, prepare|curvaturebooster, motorcycle, dijkstras:197423604, t(dijk):20060.22, t(period):3988.25, t(lazy):5204.11, t(neighbor):8068.73, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3111, usedMB:1886
» 13 Jan 2016 06:32:50.958 Wed Jan 13 06:32:50 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 0, updates:0, nodes: 9 051 466, shortcuts:0, dijkstras:35 080 163, t(dijk):26.52, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:138MB, totalMB:3111, usedMB:2246
» 13 Jan 2016 06:33:01.581 Wed Jan 13 06:33:00 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 1 810 280, updates:0, nodes: 7 241 186, shortcuts:924, dijkstras:35 801 126, t(dijk):31.5, t(period):0.0, t(lazy):0.0, t(neighbor):7.41, meanDegree:0, algo:138MB, totalMB:3111, usedMB:2344
» 13 Jan 2016 06:34:44.602 Wed Jan 13 06:34:43 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 3 620 560, updates:1, nodes: 5 430 906, shortcuts:977 607, dijkstras:67 358 993, t(dijk):93.41, t(period):50.87, t(lazy):0.0, t(neighbor):32.79, meanDegree:1, algo:138MB, totalMB:3111, usedMB:2239
» 13 Jan 2016 06:39:48.512 Wed Jan 13 06:39:47 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 5 430 840, updates:2, nodes: 3 620 626, shortcuts:2 111 055, dijkstras:96 212 734, t(dijk):348.14, t(period):265.36, t(lazy):0.0, t(neighbor):65.83, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2074
» 13 Jan 2016 06:44:15.022 Wed Jan 13 06:44:14 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 7 241 120, updates:3, nodes: 1 810 346, shortcuts:3 719 298, dijkstras:118 061 112, t(dijk):569.45, t(period):421.33, t(lazy):0.0, t(neighbor):113.37, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2052
» 13 Jan 2016 06:50:21.315 Wed Jan 13 06:50:20 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 279 264, shortcuts:5 613 251, dijkstras:144 636 675, t(dijk):887.89, t(period):548.24, t(lazy):77.93, t(neighbor):192.68, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2276
» 13 Jan 2016 06:58:11.937 Wed Jan 13 06:58:11 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:1583, new shortcuts: 6 517 955, prepare|curvaturefastest, motorcycle, dijkstras:172875728, t(dijk):1329.82, t(period):587.42, t(lazy):205.93, t(neighbor):441.94, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3111, usedMB:2205
» 13 Jan 2016 06:58:11.960 Wed Jan 13 06:58:11 +0100 2016, (GraphHopper.java:1426) INFO : flushing graph CH|motorcycle|RAM_STORE|3D|NoExt|4,13,3,2,2, details:edges:11 314 739(346MB), nodes:9 051 466(139MB), name:(1MB), geo:81 465 595(311MB), bounds:5.863066148677457,25.196558055204704,45.81184228834157,60.22003669783555,-44.0,3005.0, CHGraph|curvature|motorcycle, shortcuts:6 460 754, nodesCH:(70MB), CHGraph|curvaturebooster|motorcycle, shortcuts:8 009 827, nodesCH:(70MB), CHGraph|curvaturefastest|motorcycle, shortcuts:6 517 955, nodesCH:(70MB), totalMB:3111, usedMB:2210)

I think the Issue is not related to subnetwork searching.

I am not sure if it is related to #128. When I run CH on the new weighting only it works fast. When I run CH on the two older weightings it is still ok.

Edit:
When reviewing my Log, it seems like there is a problem with the curvautrebooster weighting. I will try a CH import on only that weighting.

Best,
Robin

karussell · January 13, 2016, 9:52am

The import itself runs on three threads: two that read from disc and one that gets this information to build the graph. See this issue for more background info: Why do we have static edge and node IDs? · Issue #556 · graphhopper/graphhopper · GitHub

And afterwards some post processing is done on 1 thread and finally the CH preparations are done in one thread each but default is maximum 1 thread as the memory requirements multiplies for every additional thread.

should be enough?

just try to decrease and see if it is significantly slower or increase if you have more to see if it changes speed. But judging from the logs the memory should not be an issue

Here is the shortened log from tonight:

Interesting gap then. Hmmh, if no GC issue then this could be related to the old issue I mentioned which would be ugly to debug but very nice to fix … btw: do you observer the same significant delay/gap for smaller regions? E.g. try just D, A and CH. (Trying just one region might not be sufficient to proof as there could be a ‘strange’ topology in e.g. only CH which makes the gap disappearing when trying only D)

If you compare the three profiles it gets interesting:

» 13 Jan 2016 00:43:43.843 Wed Jan 13 00:43:43 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 276 203, shortcuts:5 682 169, dijkstras:143 145 301, t(dijk):975.67, t(period):646.94, t(lazy):80.33, t(neighbor):185.45, meanDegree:3, algo:138MB, totalMB:3145, usedMB:2048
» 13 Jan 2016 00:49:27.191 Wed Jan 13 00:49:26 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:1534, new shortcuts: 6 460 754, prepare|curvature, motorcycle, dijkstras:165498373, t(dijk):1295.82, t(period):690.27, t(lazy):183.08, t(neighbor):339.52, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3145, usedMB:2280

» 13 Jan 2016 02:47:36.206 Wed Jan 13 02:47:35 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 397 669, shortcuts:6 564 311, dijkstras:146 853 590, t(dijk):6721.93, t(period):3394.38, t(lazy):1080.24, t(neighbor):1240.13, meanDegree:3, algo:138MB, totalMB:3111, usedMB:2046
» 13 Jan 2016 06:31:48.657 Wed Jan 13 06:31:47 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:20541, new shortcuts: 8 009 827, prepare|curvaturebooster, motorcycle, dijkstras:197423604, t(dijk):20060.22, t(period):3988.25, t(lazy):5204.11, t(neighbor):8068.73, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3111, usedMB:1886

» 13 Jan 2016 06:50:21.315 Wed Jan 13 06:50:20 +0100 2016, (PrepareContractionHierarchies.java:294) INFO : 9 051 400, updates:4, nodes: 279 264, shortcuts:5 613 251, dijkstras:144 636 675, t(dijk):887.89, t(period):548.24, t(lazy):77.93, t(neighbor):192.68, meanDegree:2, algo:138MB, totalMB:3111, usedMB:2276
» 13 Jan 2016 06:58:11.937 Wed Jan 13 06:58:11 +0100 2016, (PrepareContractionHierarchies.java:364) INFO : took:1583, new shortcuts: 6 517 955, prepare|curvaturefastest, motorcycle, dijkstras:172875728, t(dijk):1329.82, t(period):587.42, t(lazy):205.93, t(neighbor):441.94, meanDegree:1, initSize:9051466, periodic:20, lazy:10, neighbor:20, totalMB:3111, usedMB:2205

The time for the lazy and neighbour updates is significant higher. And after the 4th update a lot more nodes (400K vs. 280K) are not contracted.

boldtrn · January 13, 2016, 4:31pm

Hi Peter,

thanks for that detailed post.

But the memory multiplies only for the CH step which shouldn’t be to much (in my case maybe 200-300MB)? Or is the whole graph, location index and so on replicated?

Is there a way to find out if this is a GC issue? Increase RAM?[quote=“karussell, post:4, topic:400”]
E.g. try just D, A and CH
[/quote]

Thanks I will just try that with increased RAM.

Austria was ok so far I guess:

2016-01-13 15:29:16,188 [main] INFO  com.graphhopper.GraphHopper - 1/1 calling prepare.doWork for curvaturebooster|motorcycle ... (totalMB:5400, usedMB:756)
2016-01-13 15:29:24,519 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 0, updates:0, nodes: 1?207?223, shortcuts:0, dijkstras:4?455?381, t(dijk):3.3, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:18MB, totalMB:5400, usedMB:862
2016-01-13 15:29:26,900 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 241?440, updates:0, nodes: 965?783, shortcuts:144, dijkstras:4?547?480, t(dijk):4.84, t(period):0.0, t(lazy):0.0, t(neighbor):1.83, meanDegree:1, algo:18MB, totalMB:5400, usedMB:870
2016-01-13 15:30:57,783 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 482?880, updates:1, nodes: 724?343, shortcuts:55?029, dijkstras:8?379?025, t(dijk):89.55, t(period):81.57, t(lazy):0.0, t(neighbor):5.77, meanDegree:2, algo:18MB, totalMB:5400, usedMB:957
2016-01-13 15:33:17,077 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 724?320, updates:2, nodes: 482?903, shortcuts:240?590, dijkstras:11?634?677, t(dijk):222.21, t(period):193.35, t(lazy):0.0, t(neighbor):17.96, meanDegree:1, algo:18MB, totalMB:5400, usedMB:1062
2016-01-13 15:35:16,758 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 965?760, updates:3, nodes: 241?463, shortcuts:452?055, dijkstras:14?283?345, t(dijk):336.04, t(period):281.39, t(lazy):0.0, t(neighbor):32.29, meanDegree:1, algo:18MB, totalMB:5400, usedMB:1159
2016-01-13 15:38:31,813 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 1?207?200, updates:4, nodes: 48?589, shortcuts:732?895, dijkstras:17?547?557, t(dijk):523.57, t(period):317.76, t(lazy):60.39, t(neighbor):81.35, meanDegree:3, algo:18MB, totalMB:5400, usedMB:1266
2016-01-13 15:44:42,198 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - took:925, new shortcuts: 864?979, prepare|curvaturebooster, motorcycle, dijkstras:21005115, t(dijk):889.02, t(period):367.51, t(lazy):183.98, t(neighbor):216.01, meanDegree:1, initSize:1207223, periodic:20, lazy:10, neighbor:20, totalMB:5400, usedMB:1310
2016-01-13 15:44:42,206 [main] INFO  com.graphhopper.GraphHopper - flushing graph CH|motorcycle|RAM_STORE|3D|NoExt|4,13,3,2,2, details:edges:1?453?990(45MB), nodes:1?207?223(19MB), name:(1MB), geo:16?322?170(63MB), bounds:9.52804854947437,17.16501527648453,46.40013027340465,49.027549826224515,0.0,2941.0, CHGraph|curvaturebooster|motorcycle, shortcuts:864?979, nodesCH:(10MB), totalMB:5400, usedMB:1310)

Switzerland looks okay as well:

2016-01-13 15:56:52,129 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 0, updates:0, nodes: 755?495, shortcuts:0, dijkstras:2?808?312, t(dijk):2.08, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:11MB, totalMB:5448, usedMB:522
2016-01-13 15:56:53,516 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 151?080, updates:0, nodes: 604?415, shortcuts:180, dijkstras:2?864?707, t(dijk):2.8, t(period):0.0, t(lazy):0.0, t(neighbor):0.96, meanDegree:1, algo:11MB, totalMB:5448, usedMB:531
2016-01-13 15:57:55,587 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 302?160, updates:1, nodes: 453?335, shortcuts:42?530, dijkstras:5?305?999, t(dijk):60.69, t(period):55.6, t(lazy):0.0, t(neighbor):3.72, meanDegree:1, algo:11MB, totalMB:5448, usedMB:583
2016-01-13 15:58:56,867 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 453?240, updates:2, nodes: 302?255, shortcuts:160?949, dijkstras:7?392?208, t(dijk):118.01, t(period):99.51, t(lazy):0.0, t(neighbor):11.64, meanDegree:2, algo:11MB, totalMB:5448, usedMB:644
2016-01-13 15:59:57,855 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 604?320, updates:3, nodes: 151?175, shortcuts:310?284, dijkstras:9?162?931, t(dijk):175.25, t(period):135.3, t(lazy):0.0, t(neighbor):23.48, meanDegree:2, algo:11MB, totalMB:5448, usedMB:715
2016-01-13 16:02:39,097 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 755?400, updates:4, nodes: 31?560, shortcuts:500?317, dijkstras:11?405?255, t(dijk):331.28, t(period):183.14, t(lazy):42.22, t(neighbor):59.19, meanDegree:2, algo:11MB, totalMB:5448, usedMB:780
2016-01-13 16:07:11,962 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - took:624, new shortcuts: 598?376, prepare|curvaturebooster, motorcycle, dijkstras:13975275, t(dijk):600.51, t(period):195.61, t(lazy):142.42, t(neighbor):167.96, meanDegree:1, initSize:755495, periodic:20, lazy:10, neighbor:20, totalMB:5448, usedMB:815
2016-01-13 16:07:11,970 [main] INFO  com.graphhopper.GraphHopper - flushing graph CH|motorcycle|RAM_STORE|3D|NoExt|4,13,3,2,2, details:edges:914?397(28MB), nodes:755?495(12MB), name:(1MB), geo:8?519?964(33MB), bounds:5.952895379503713,10.505562882994775,45.81184228834157,47.808391924390016,0.0,3005.0, CHGraph|curvaturebooster|motorcycle, shortcuts:598?376, nodesCH:(6MB), totalMB:5448, usedMB:815)

Germany looks a bit more difficult right now. The imports runs for more than an hour now. CH is currently taking one hour and still going on:

2016-01-13 16:26:10,063 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 0, updates:0, nodes: 7?101?531, shortcuts:0, dijkstras:27?859?855, t(dijk):27.45, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:108MB, totalMB:5470, usedMB:2181
2016-01-13 16:26:27,020 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 1?420?300, updates:0, nodes: 5?681?231, shortcuts:646, dijkstras:28?421?638, t(dijk):38.35, t(period):0.0, t(lazy):0.0, t(neighbor):13.69, meanDegree:0, algo:108MB, totalMB:5470, usedMB:2261
2016-01-13 16:29:20,030 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 2?840?600, updates:1, nodes: 4?260?931, shortcuts:837?318, dijkstras:53?712?111, t(dijk):165.26, t(period):56.19, t(lazy):0.0, t(neighbor):73.62, meanDegree:1, algo:108MB, totalMB:5005, usedMB:1704
2016-01-13 16:43:04,311 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 4?260?900, updates:2, nodes: 2?840?631, shortcuts:1?866?947, dijkstras:76?875?163, t(dijk):935.73, t(period):650.4, t(lazy):0.0, t(neighbor):171.66, meanDegree:1, algo:108MB, totalMB:5005, usedMB:2411
2016-01-13 16:58:16,197 [curvaturebooster_motorcycle] INFO  com.graphhopper.routing.ch.PrepareContractionHierarchies - 5?681?200, updates:3, nodes: 1?420?331, shortcuts:3?409?993, dijkstras:95?720?387, t(dijk):1792.45, t(period):1117.92, t(lazy):0.0, t(neighbor):375.06, meanDegree:2, algo:108MB, totalMB:5157, usedMB:2069

If you compare the sizes it seems valid that Germany takes that much longer.

I also compared pure Algorithm Speed for some routes. The booster (thats the problematic one), takes sometimes longer (up to 25%) but in general its comparable.

Any idea what could be the reason for this?

Best,
Robin

karussell · January 13, 2016, 7:10pm

It is the shortcuts and some datastructures for the preparation

Is there a way to find out if this is a GC issue? Increase RAM?

You could log GC activity and if it increases too much you have a problem. Or you profile the app.

Any idea what could be the reason for this?

The preparation is heuristical and depends a lot on the weighting and resulting topology. Do you have different access properties or maybe some infinities or NaN values in the weighting?

If you compare the sizes it seems valid that Germany takes that much longer.

Yes, that is true. But when you compare the time it takes for the different weightings and if there is a difference it is then easier to handle e.g. for debugging