Benchmark stops with PointOutOfBoundsException

[otbutz]

I tried to run the benchmark script with the defaults to measure #2973. Unfortunately, the benchmark script stops with an exception for the master( tested with 328e3d2 ).

benchmark/benchmark.sh

4 - big map, outdoor: node-based CH + landmarks (edge- & node-based for LM)
2024-04-17 11:11:35.162 [main] INFO  c.g.routing.lm.LMPreparationHandler - Loaded built-in landmark splitting collection from jar:file:/home/tbutz/Entwicklung/repos/graphhopper/tools/target/graphhopper-tools-9.0-SNAPSHOT-jar-with-dependencies.jar!/com/graphhopper/routing/lm/map.geo.json
2024-04-17 11:11:35.169 [main] INFO  com.graphhopper.GraphHopper - version 9.0|2024-04-17T09:09:22Z (9,21,6,5,2,9)
2024-04-17 11:11:35.362 [main] INFO  com.graphhopper.GraphHopper - No custom areas are used, custom_areas.directory not given
2024-04-17 11:11:35.365 [main] INFO  com.graphhopper.GraphHopper - No country rules available
2024-04-17 11:11:35.365 [main] INFO  com.graphhopper.GraphHopper - start creating graph from core/files/andorra.osm.pbf
2024-04-17 11:11:35.385 [main] INFO  com.graphhopper.GraphHopper - using foot|RAM_STORE|2D|no_turn_cost|nodes:9,edges:21,geometry:6,location_index:5,string_index:2,nodesCH:0,shortcuts:9, memory:totalMB:19627, usedMB:820
2024-04-17 11:11:35.396 [main] INFO  c.g.reader.osm.WaySegmentParser - Start reading OSM file: 'core/files/andorra.osm.pbf'
2024-04-17 11:11:35.396 [main] INFO  c.g.reader.osm.WaySegmentParser - pass1 - start
2024-04-17 11:11:35.489 [main] INFO  c.g.reader.osm.WaySegmentParser - pass1 - start reading OSM ways
2024-04-17 11:11:35.518 [main] INFO  c.g.reader.osm.WaySegmentParser - pass1 - start reading OSM relations
2024-04-17 11:11:35.523 [main] INFO  c.g.reader.osm.WaySegmentParser - pass1 - finished, processed ways: 2,725, accepted ways: 1,615, way nodes: 38,556, relations: 74, totalMB:19627, usedMB:1127
2024-04-17 11:11:35.524 [main] INFO  c.g.reader.osm.WaySegmentParser - pass1 - finished, took: 127,17ms
2024-04-17 11:11:35.526 [main] INFO  c.g.reader.osm.WaySegmentParser - Creating graph. Node count (pillar+tower): 38556, totalMB:19627, usedMB:1127
2024-04-17 11:11:35.526 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - start
2024-04-17 11:11:35.545 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - start reading OSM nodes
2024-04-17 11:11:35.601 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - start reading OSM ways
2024-04-17 11:11:35.735 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - start reading OSM relations
2024-04-17 11:11:35.736 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - finished, processed ways: 2,725, way nodes: 38,556, nodes with tags: 92, node tag capacity: 1,056,768, ignored barriers at junctions: 0
2024-04-17 11:11:35.737 [main] INFO  c.g.reader.osm.WaySegmentParser - pass2 - finished, took: 210,53ms
2024-04-17 11:11:35.741 [main] INFO  c.g.reader.osm.WaySegmentParser - Finished reading OSM file. pass1: 0s,  pass2: 0s,  total: 0s
2024-04-17 11:11:35.741 [main] INFO  com.graphhopper.reader.osm.OSMReader - Finished reading OSM file: /home/tbutz/Entwicklung/repos/graphhopper/core/files/andorra.osm.pbf, nodes: 2,385, edges: 2,820, zero distance edges: 6
2024-04-17 11:11:35.747 [main] INFO  c.g.r.s.PrepareRoutingSubnetworks - Start marking subnetworks, prepare.min_network_size: 10000, threads: 1, nodes: 2,385, edges: 2,820, jobs: [profile_no_tc_subnetwork|com.graphhopper.routing.weighting.custom.CustomWeighting@61ce23ac], totalMB:19627, usedMB:1434
2024-04-17 11:11:35.792 [ForkJoinPool-1-worker-1] INFO  c.g.r.s.PrepareRoutingSubnetworks - profile_no_tc - Found 470 subnetworks (424 single edges and 46 components with more than one edge, total nodes: 5640), took: 0.028205588s
2024-04-17 11:11:35.802 [ForkJoinPool-1-worker-1] INFO  c.g.r.s.PrepareRoutingSubnetworks - profile_no_tc - Marked 469 subnetworks (biggest: 568 edges) -> 1 components(s) remain (smallest: 4414, biggest: 4414 edges), total marked edges: 401, took: 0.003553247s
2024-04-17 11:11:35.806 [main] INFO  c.g.r.s.PrepareRoutingSubnetworks - Finished finding and marking subnetworks for 1 jobs, took: 0.059996214s, totalMB:19627, usedMB:1537
2024-04-17 11:11:35.807 [main] INFO  com.graphhopper.GraphHopper - nodes: 2,385, edges: 2,820
2024-04-17 11:11:35.912 [main] INFO  c.g.storage.index.LocationIndexTree - location index created in 0.03969434s, size:4,766, leafs:1,132, precision:300, depth:4, checksum:597, entries:[16, 16, 4, 4], entriesPerLeaf:4.2102475
2024-04-17 11:11:35.917 [main] INFO  c.g.routing.lm.LMPreparationHandler - Creating LM preparations, totalMB:19627, usedMB:1844
2024-04-17 11:11:35.922 [ForkJoinPool-3-worker-1] INFO  c.g.routing.lm.LMPreparationHandler - 1/1 calling LM prepare.doWork for profile_no_tc ... (totalMB:19627, usedMB:1946)
2024-04-17 11:11:35.924 [profile_no_tc] INFO  c.g.routing.lm.PrepareLandmarks - Start calculating 16 landmarks, weighting:LM_BFS|custom|com.graphhopper.routing.weighting.custom.CustomWeighting@1a47fbb4, totalMB:19627, usedMB:1946
2024-04-17 11:11:36.102 [profile_no_tc] INFO  c.g.routing.lm.PrepareLandmarks - Calculated landmarks for 1 subnetworks, took:0s => { "type": "FeatureCollection", "features": [{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.697066, 42.532062]},  "properties":{"node_index":1836,"subnetwork":1,"lm_index":0}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.4920728, 42.4845742]},  "properties":{"node_index":914,"subnetwork":1,"lm_index":1}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.6132318, 42.5538863]},  "properties":{"node_index":2262,"subnetwork":1,"lm_index":2}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.4798844, 42.5789323]},  "properties":{"node_index":1862,"subnetwork":1,"lm_index":3}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.6961725, 42.5317807]},  "properties":{"node_index":2154,"subnetwork":1,"lm_index":4}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.5089412, 42.619261]},  "properties":{"node_index":2086,"subnetwork":1,"lm_index":5}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.541352, 42.5078166]},  "properties":{"node_index":82,"subnetwork":1,"lm_index":6}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.6535302, 42.5809697]},  "properties":{"node_index":1911,"subnetwork":1,"lm_index":7}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.5295996, 42.5539542]},  "properties":{"node_index":2005,"subnetwork":1,"lm_index":8}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.5544609, 42.5174658]},  "properties":{"node_index":1267,"subnetwork":1,"lm_index":9}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.5955201, 42.5364987]},  "properties":{"node_index":2198,"subnetwork":1,"lm_index":10}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.6670917, 42.5873426]},  "properties":{"node_index":2356,"subnetwork":1,"lm_index":11}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.512272, 42.5018015]},  "properties":{"node_index":2169,"subnetwork":1,"lm_index":12}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.4423627, 42.5152544]},  "properties":{"node_index":2061,"subnetwork":1,"lm_index":13}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.7338324, 42.5422862]},  "properties":{"node_index":1834,"subnetwork":1,"lm_index":14}},{ "type": "Feature", "geometry": {"type": "Point", "coordinates": [1.5841182, 42.5366726]},  "properties":{"node_index":1476,"subnetwork":1,"lm_index":15}}]}, stored weights:16, nodes:2385, totalMB:19627, usedMB:1946
2024-04-17 11:11:36.102 [profile_no_tc] INFO  c.g.routing.lm.LMPreparationHandler - LM profile_no_tc finished totalMB:19627, usedMB:1946
2024-04-17 11:11:36.102 [main] INFO  c.g.routing.lm.LMPreparationHandler - Finished LM preparation, totalMB:19627, usedMB:1946
2024-04-17 11:11:36.107 [main] INFO  c.g.routing.ch.CHPreparationHandler - Creating CH preparations, totalMB:19627, usedMB:2049
2024-04-17 11:11:36.112 [main] INFO  c.g.routing.ch.CHPreparationHandler - 1/1 calling CH prepare.doWork for profile 'profile_no_tc' NODE_BASED ... (totalMB:19627, usedMB:2049)
2024-04-17 11:11:36.114 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - Creating CH prepare graph, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.118 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - Building CH prepare graph, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.123 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - Finished building CH prepare graph, took: 0.004892844s, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.125 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - Building initial queue of nodes to be contracted: 2385 nodes, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.140 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - Finished building queue, took: 0.015270958s, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.142 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:      2,385, shortcuts:          0, updates:  0, checked-nodes:          0, t(total):   0.03,  t(period):   0.01, t(lazy):   0.00, t(neighbor):   0.00, t(contr):   0.00, t(other) :   0.01, dijkstra-ratio:  25.34%, meanDegree: 1.18, dijkstras:      8,370, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.162 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:      1,910, shortcuts:          5, updates:  0, checked-nodes:        477, t(total):   0.05,  t(period):   0.01, t(lazy):   0.00, t(neighbor):   0.01, t(contr):   0.01, t(other) :   0.02, dijkstra-ratio:  26.95%, meanDegree: 1.00, dijkstras:      9,752, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.167 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:      1,433, shortcuts:          5, updates:  0, checked-nodes:        954, t(total):   0.05,  t(period):   0.01, t(lazy):   0.00, t(neighbor):   0.01, t(contr):   0.01, t(other) :   0.02, dijkstra-ratio:  26.90%, meanDegree: 1.00, dijkstras:     10,370, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.179 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:        956, shortcuts:         32, updates:  0, checked-nodes:      1,431, t(total):   0.06,  t(period):   0.01, t(lazy):   0.00, t(neighbor):   0.01, t(contr):   0.01, t(other) :   0.02, dijkstra-ratio:  27.65%, meanDegree: 1.94, dijkstras:     13,104, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.196 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:        481, shortcuts:        319, updates:  0, checked-nodes:      1,908, t(total):   0.08,  t(period):   0.01, t(lazy):   0.01, t(neighbor):   0.02, t(contr):   0.02, t(other) :   0.02, dijkstra-ratio:  29.75%, meanDegree: 2.23, dijkstras:     18,593, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.205 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:         34, shortcuts:        868, updates:  0, checked-nodes:      2,385, t(total):   0.09,  t(period):   0.01, t(lazy):   0.01, t(neighbor):   0.03, t(contr):   0.02, t(other) :   0.02, dijkstra-ratio:  32.15%, meanDegree: 2.66, dijkstras:     25,845, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.208 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - node, nodes:          0, shortcuts:        942, updates:  0, checked-nodes:      2,420, t(total):   0.09,  t(period):   0.01, t(lazy):   0.01, t(neighbor):   0.03, t(contr):   0.02, t(other) :   0.03, dijkstra-ratio:  31.64%, meanDegree: 0.92, dijkstras:     26,350, mem:        0MB, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.210 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - new shortcuts: 942, initSize:2,385, com.graphhopper.routing.weighting.custom.CustomWeighting@12d16b94, periodic:0, lazy:100, neighbor:100, t(total):   0.09,  t(period):   0.01, t(lazy):   0.01, t(neighbor):   0.03, t(contr):   0.02, t(other) :   0.03, dijkstra-ratio:  31.48%, lazy-overhead: 1%, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.210 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - shortcuts that exceed maximum weight: 0
2024-04-17 11:11:36.210 [profile_no_tc] INFO  c.g.r.c.PrepareContractionHierarchies - took: 0s, graph now - num edges: 2,820, num nodes: 2,385, num shortcuts: 942
2024-04-17 11:11:36.215 [main] INFO  c.g.routing.ch.CHPreparationHandler - Finished CH preparation, totalMB:19627, usedMB:2151
2024-04-17 11:11:36.221 [main] INFO  com.graphhopper.GraphHopper - flushing graph foot|RAM_STORE|2D|no_turn_cost|nodes:9,edges:21,geometry:6,location_index:5,string_index:2,nodesCH:0,shortcuts:9, details:edges: 2,820(1MB), nodes: 2,385(1MB), bounds: 1.4088716,1.8164837,42.4292405,42.6942662, name:(1MB), geo:53,180(1MB), totalMB:19627, usedMB:2151)
2024-04-17 11:11:36.227 [main] INFO  com.graphhopper.GraphHopper - flushed graph totalMB:19627, usedMB:2151)
2024-04-17 11:11:36.312 [main] INFO  com.graphhopper.tools.Measurement - unit_tests.out_edge_state_next: sum:0.055s, time/call:0.11µs, dummy: 1458144
2024-04-17 11:11:36.375 [main] INFO  com.graphhopper.tools.Measurement - unit_tests.all_edge_state_next: sum:0.049s, time/call:0.098µs, dummy: 1576267
2024-04-17 11:11:36.412 [main] INFO  com.graphhopper.tools.Measurement - unit_tests.get_edge_state: sum:0.029s, time/call:0.058µs, dummy: 938300673
2024-04-17 11:11:36.634 [main] INFO  com.graphhopper.tools.Measurement - location_index: sum:0.15s, time/call:0.015ms, dummy: 15539814
2024-04-17 11:11:36.983 [main] INFO  com.graphhopper.tools.Measurement - routingLM4: sum:0.218s, time/call:0.873ms, dummy: 189533
2024-04-17 11:11:37.018 [main] INFO  com.graphhopper.tools.Measurement - routingLM4_alt: sum:0.026s, time/call:2.578ms, dummy: 5784
2024-04-17 11:11:37.219 [main] INFO  com.graphhopper.tools.Measurement - routingLM8: sum:0.139s, time/call:0.555ms, dummy: 189533
2024-04-17 11:11:37.245 [main] INFO  com.graphhopper.tools.Measurement - routingLM8_alt: sum:0.022s, time/call:2.178ms, dummy: 5784
2024-04-17 11:11:37.363 [main] INFO  com.graphhopper.tools.Measurement - routingLM12: sum:0.084s, time/call:0.337ms, dummy: 189533
2024-04-17 11:11:37.379 [main] INFO  com.graphhopper.tools.Measurement - routingLM12_alt: sum:0.013s, time/call:1.306ms, dummy: 5784
2024-04-17 11:11:37.439 [main] INFO  com.graphhopper.tools.Measurement - unit_testsCH.get_edge_state: sum:0.029s, time/call:0.058µs, dummy: 1253795688
2024-04-17 11:11:37.592 [main] INFO  com.graphhopper.tools.Measurement - unit_testsCH.out_edge_next: sum:0.114s, time/call:0.229µs, dummy: -1755963229
2024-04-17 11:11:37.750 [main] INFO  com.graphhopper.tools.Measurement - unit_testsCH.out_edge_get_weight: sum:0.115s, time/call:0.229µs, dummy: 1354335068
2024-04-17 11:11:37.982 [main] ERROR com.graphhopper.tools.Measurement - Problem while measuring measurements/measurement-big-outdoor-gh
java.lang.RuntimeException: errors should NOT happen in Measurement! 42.6111343,1.4088715; 42.5679299,1.4886214 (Hints:{ch.disable=false, stall_on_demand=true, lm.disable=true, lm.active_landmarks=-1, instructions=true, way_point_max_distance=0}) => [com.graphhopper.util.exceptions.PointOutOfBoundsException: Point 0 is out of bounds: 42.6111343,1.4088715, the bounds are: 1.4088716,1.8164837,42.4292405,42.6942662]
        at com.graphhopper.tools.Measurement.lambda$measureRouting$10(Measurement.java:595)
        at com.graphhopper.util.MiniPerfTest.start(MiniPerfTest.java:46)
        at com.graphhopper.tools.Measurement.measureRouting(Measurement.java:539)
        at com.graphhopper.tools.Measurement.start(Measurement.java:233)
        at com.graphhopper.tools.Measurement.main(Measurement.java:84)

[karussell]

The first coordinate is just out of bounds. We do not use andorra in our tests and probably we should not provide this as default as andorra is not well suited for this automated test as the coverage has relative big holes for this small area.

For your tests can you try with e.g. bavaria?

[otbutz]

The first coordinate is just out of bounds. We do not use andorra in our tests and probably we should not provide this as default as andorra is not well suited for this automated test as the coverage has relative big holes for this small area.

Should we switch to an automated download instead or abort with a warning if no parameters have been passed?

For your tests can you try with e.g. bavaria?

👍

[karussell]

Yes, aborting makes sense.

[otbutz]

I'll draft a PR

[easbar]

I just changed the script to use leipzig.osm.pbf as default map, does this help? But maybe you don't really want to run all of benchmark.sh and just run the Measurement.java class a single time. It already aborts if no path to a map is given.