GIScience / openrouteservice

🌍 The open source route planner api with plenty of features.
https://openrouteservice.org
GNU General Public License v3.0
1.43k stars 391 forks source link

ArrayIndexOutOfBoundsException from fast isochrones #1120

Closed starzu-sentio closed 1 year ago

starzu-sentio commented 2 years ago

Here's what I did

I'm trying to generate data for Europe on k8s with pod limits set to 8 vCPU and 220GB RAM.

Docker image version: v6.7.0 Source file: http://download.geofabrik.de/europe-latest.osm.pbf

Env variables:

JAVA_OPTS="-Xmx180G -Djava.awt.headless=true -server -XX:TargetSurvivorRatio=75 -XX:SurvivorRatio=64 -XX:MaxTenuringThreshold=3 -XX:+UseG1GC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=8 -XX:ErrorFile=/var/log/hs_err_pid%p.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/ors-core/data/"
CATALINA_OPTS="-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9001 -Dcom.sun.management.jmxremote.rmi.port=9001 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=localhost"

ORS config:

{
  "ors": {
    "services": {
      "matrix": {
        "enabled": true,
        "maximum_routes": 10000,
        "maximum_routes_flexible": 25,
        "maximum_search_radius": 5000,
        "maximum_visited_nodes": 100000,
        "allow_resolve_locations": true,
        "attribution": "openrouteservice.org, OpenStreetMap contributors"
      },
      "isochrones": {
        "enabled": true,
        "maximum_range_distance": [
          {
            "profiles": "any",
            "value": 50000
          },
          {
            "profiles": "driving-car, driving-hgv",
            "value": 500000
          }
        ],
        "maximum_range_time": [
          {
            "profiles": "any",
            "value": 10800
          },
          {
            "profiles": "driving-car, driving-hgv",
            "value": 10800
          }
        ],
        "fastisochrones": {
          "maximum_range_distance": [
            {
              "profiles": "any",
              "value": 50000
            },
            {
              "profiles": "driving-car, driving-hgv",
              "value": 500000
            }
          ],
          "maximum_range_time": [
            {
              "profiles": "any",
              "value": 10800
            },
            {
              "profiles": "driving-car, driving-hgv",
              "value": 10800
            }
          ],
          "profiles": {
            "default_params": {
              "enabled": true,
              "threads": 8,
              "weightings": "recommended",
              "maxcellnodes": 5000
            },
            "profile-hgv": {
              "enabled": true,
              "threads": 8,
              "weightings": "recommended, shortest",
              "maxcellnodes": 5000
            }
          }
        },
        "maximum_intervals": 10,
        "maximum_locations": 2,
        "allow_compute_area": true
      },
      "routing": {
        "enabled": true,
        "mode": "normal",
        "routing_name": "openrouteservice routing",
        "sources": [
          "data/osm_file.pbf"
        ],
        "init_threads": 8,
        "attribution": "openrouteservice.org, OpenStreetMap contributors",
        "elevation_preprocessed": false,
        "profiles": {
          "active": [
            "car",
            "hgv"
          ],
          "default_params": {
            "encoder_flags_size": 8,
            "graphs_root_path": "data/graphs",
            "elevation": false,
            "elevation_provider": "multi",
            "elevation_cache_path": "cgiar_provider",
            "elevation_cache_clear": false,
            "instructions": false,
            "maximum_distance": 10000000,
            "maximum_distance_dynamic_weights": 10000000,
            "maximum_distance_avoid_areas": 10000000,
            "maximum_waypoints": 200,
            "maximum_snapping_radius": 10000,
            "maximum_avoid_polygon_area": 200000000,
            "maximum_avoid_polygon_extent": 20000,
            "maximum_distance_alternative_routes": 10000000,
            "maximum_alternative_routes": 3,
            "maximum_distance_round_trip_routes": 20000000,
            "maximum_speed_lower_bound": 80,
            "preparation": {
              "min_network_size": 200,
              "min_one_way_network_size": 200,
              "methods": {
                "lm": {
                  "enabled": true,
                  "threads": 8,
                  "weightings": "recommended,shortest",
                  "landmarks": 16
                }
              }
            },
            "execution": {
              "methods": {
                "lm": {
                  "disabling_allowed": true,
                  "active_landmarks": 8
                }
              }
            }
          },
          "profile-car": {
            "profiles": "driving-car",
            "parameters": {
              "encoder_flags_size": 8,
              "encoder_options": "turn_costs=true|block_fords=false|use_acceleration=true",
              "maximum_distance": 10000000,
              "elevation": false,
              "preparation": {
                "min_network_size": 200,
                "min_one_way_network_size": 200,
                "methods": {
                  "ch": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "fastest"
                  },
                  "lm": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "fastest,shortest",
                    "landmarks": 16
                  },
                  "core": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "fastest,shortest",
                    "landmarks": 64,
                      "lmsets": "highways,tollways;highways;tollways;allow_all"
                  }
                }
              },
              "execution": {
                "methods": {
                  "ch": {
                    "disabling_allowed": true
                  },
                  "lm": {
                    "disabling_allowed": true,
                    "active_landmarks": 6
                  },
                  "core": {
                    "disabling_allowed": true,
                    "active_landmarks": 6
                  }
                }
              },
              "ext_storages": {
                "WayCategory": {},
                "HeavyVehicle": {},
                "WaySurfaceType": {},
                "RoadAccessRestrictions": {
                  "use_for_warnings": true
                }
              }
            }
          },
          "profile-hgv": {
            "profiles": "driving-hgv",
            "parameters": {
              "encoder_flags_size": 8,
              "encoder_options": "turn_costs=true|block_fords=false|use_acceleration=true",
              "maximum_distance": 10000000,
              "elevation": false,
              "preparation": {
                "min_network_size": 200,
                "min_one_way_network_size": 200,
                "methods": {
                  "ch": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "recommended"
                  },
                  "lm": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "recommended,shortest",
                    "landmarks": 16
                  },
                  "core": {
                    "enabled": true,
                    "threads": 8,
                    "weightings": "recommended,shortest",
                    "landmarks": 64,
                    "lmsets": "highways,tollways;highways;tollways;allow_all"
                  }
                }
              },
              "execution": {
                "methods": {
                  "ch": {
                    "disabling_allowed": true
                  },
                  "lm": {
                    "disabling_allowed": true,
                    "active_landmarks": 6
                  },
                  "core": {
                    "disabling_allowed": true,
                    "active_landmarks": 6
                  }
                }
              },
              "ext_storages": {
                "WayCategory": {},
                "HeavyVehicle": {
                  "restrictions": true
                },
                "WaySurfaceType": {},
                "Tollways": {}
              }
            }
          }
        }
      }
    },
    "logging": {
      "enabled": true,
      "level_file": "DEBUG_LOGGING.json",
      "location": "/var/log/ors",
      "stdout": true
    },
    "system_message": []
  }
}

Here's what I got

ArrayIndexOutOfBoundsException (probably) during isochrones generation.

Content of /var/log/ors/ors.log:

2022-01-24 20:15:03,625 INFO [ors.Application] - Starting Application v6.7.0 on ors-builder with PID 132 (/usr/local/tomcat/webapps/ors/WEB-INF/classes started by root in /ors-core)
2022-01-24 20:15:03,627 DEBUG [ors.Application] - Running with Spring Boot v2.3.5.RELEASE, Spring v5.2.10.RELEASE
2022-01-24 20:15:03,629 INFO [ors.Application] - No active profile set, falling back to default profiles: default
2022-01-24 20:15:06,453 INFO [ors.Application] - Started Application in 3.64 seconds (JVM running for 8.48)
2022-01-24 20:15:06,489 INFO [routing.RoutingProfileManager] -  Total - 2.41 GB, Free - 1.66 GB, Max: 180 GB, Used - 762.62 MB
2022-01-24 20:15:06,489 INFO [routing.RoutingProfileManager] -       
2022-01-24 20:15:06,525 INFO [routing.RoutingProfileManager] - ====> Initializing profiles from 'data/osm_file.pbf' (8 threads) ...
2022-01-24 20:15:06,525 INFO [routing.RoutingProfileManager] -                               
2022-01-24 20:15:06,528 INFO [routing.RoutingProfileManager] -                
2022-01-24 20:15:06,547 INFO [routing.RoutingProfile] - [1] Profiles: 'driving-hgv', location: 'data/graphs/hgv'.
2022-01-24 20:15:06,547 INFO [routing.RoutingProfile] - [2] Profiles: 'driving-car', location: 'data/graphs/car'.
2022-01-25 03:43:21,447 INFO [core.PrepareCore] - 0, updates:0, nodes: 75 706 476, shortcuts:0, dijkstras:291 032 482, t(dijk):199.17, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:75184
2022-01-25 03:43:29,822 INFO [core.PrepareCore] - 0, updates:0, nodes: 75 706 476, shortcuts:0, dijkstras:291 032 482, t(dijk):208.14, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:75808
2022-01-25 04:08:51,377 INFO [core.PrepareCore] - 0, updates:0, nodes: 71 566 232, shortcuts:0, dijkstras:270 591 125, t(dijk):178.34, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:87472
2022-01-25 04:10:03,126 INFO [core.PrepareCore] - 0, updates:0, nodes: 71 566 232, shortcuts:0, dijkstras:270 591 125, t(dijk):192.96, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:90496
2022-01-25 04:16:51,403 INFO [core.PrepareCore] - 15 141 295, updates:1, nodes: 60 565 181, shortcuts:96 344, dijkstras:582 881 211, t(dijk):2023.48, t(period):1719.56, t(lazy):0.0, t(neighbor):255.53, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:96896
2022-01-25 04:24:03,914 INFO [core.PrepareCore] - 15 141 295, updates:1, nodes: 60 565 181, shortcuts:140 295, dijkstras:586 847 372, t(dijk):2441.14, t(period):2032.02, t(lazy):0.0, t(neighbor):326.93, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:107842
2022-01-25 05:00:48,837 INFO [core.PrepareCore] - 14 313 246, updates:2, nodes: 57 252 986, shortcuts:94 933, dijkstras:751 812 316, t(dijk):3031.46, t(period):2850.17, t(lazy):0.0, t(neighbor):234.68, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:84928
2022-01-25 05:04:18,600 INFO [core.PrepareCore] - 30 282 590, updates:3, nodes: 45 423 886, shortcuts:670 682, dijkstras:1 033 212 719, t(dijk):4604.29, t(period):4343.78, t(lazy):0.0, t(neighbor):457.44, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:85040
2022-01-25 05:19:02,952 INFO [core.PrepareCore] - 30 282 590, updates:3, nodes: 45 423 886, shortcuts:146 546, dijkstras:1 024 571 082, t(dijk):5478.88, t(period):5073.92, t(lazy):0.0, t(neighbor):557.17, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:96096
2022-01-25 05:28:25,285 INFO [core.PrepareCore] - 14 313 246, updates:2, nodes: 57 252 986, shortcuts:148 805, dijkstras:750 492 011, t(dijk):4547.19, t(period):4240.19, t(lazy):0.0, t(neighbor):367.7, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:105839
2022-01-25 05:43:34,759 INFO [core.PrepareCore] - 28 626 492, updates:4, nodes: 42 939 740, shortcuts:272 765, dijkstras:1 115 457 171, t(dijk):5373.9, t(period):5201.84, t(lazy):0.0, t(neighbor):430.62, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:117216
2022-01-25 06:01:42,985 INFO [core.PrepareCore] - 45 423 885, updates:5, nodes: 30 282 591, shortcuts:16 339 572, dijkstras:1 505 770 787, t(dijk):7727.58, t(period):6542.72, t(lazy):0.0, t(neighbor):1427.02, meanDegree:2, algo:1155MB, totalMB:151712, usedMB:126755
2022-01-25 06:22:01,700 INFO [core.PrepareCore] - 45 423 885, updates:5, nodes: 30 282 591, shortcuts:14 894 258, dijkstras:1 467 642 433, t(dijk):8917.29, t(period):7481.48, t(lazy):0.0, t(neighbor):1589.95, meanDegree:1, algo:1155MB, totalMB:151712, usedMB:76903
2022-01-25 06:27:41,962 INFO [core.PrepareCore] - 28 626 492, updates:4, nodes: 42 939 740, shortcuts:156 527, dijkstras:1 100 984 849, t(dijk):7847.03, t(period):7494.48, t(lazy):0.0, t(neighbor):638.71, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:80620
2022-01-25 06:37:18,286 INFO [core.PrepareCore] - 42 939 738, updates:6, nodes: 28 626 494, shortcuts:15 194 620, dijkstras:1 508 973 370, t(dijk):8296.93, t(period):7183.92, t(lazy):0.0, t(neighbor):1394.33, meanDegree:2, algo:1092MB, totalMB:151712, usedMB:82915
2022-01-25 06:59:47,032 INFO [core.PrepareCore] - 60 565 180, updates:7, nodes: 15 141 296, shortcuts:32 768 462, dijkstras:1 938 660 839, t(dijk):10888.37, t(period):8270.83, t(lazy):0.0, t(neighbor):2821.88, meanDegree:3, algo:1155MB, totalMB:151712, usedMB:98100
2022-01-25 07:21:18,846 INFO [core.PrepareCore] - 60 565 180, updates:7, nodes: 15 141 296, shortcuts:29 260 455, dijkstras:1 838 765 037, t(dijk):12165.82, t(period):9343.11, t(lazy):0.0, t(neighbor):2900.09, meanDegree:2, algo:1155MB, totalMB:151712, usedMB:106729
2022-01-25 07:28:13,194 INFO [core.PrepareCore] - 57 252 984, updates:8, nodes: 14 313 248, shortcuts:30 376 173, dijkstras:1 856 210 026, t(dijk):11074.42, t(period):8584.5, t(lazy):0.0, t(neighbor):2704.03, meanDegree:2, algo:1092MB, totalMB:151712, usedMB:107680
2022-01-25 07:37:11,717 INFO [core.PrepareCore] - 42 939 738, updates:6, nodes: 28 626 494, shortcuts:13 432 476, dijkstras:1 454 082 551, t(dijk):11705.37, t(period):10037.66, t(lazy):0.0, t(neighbor):1844.63, meanDegree:1, algo:1092MB, totalMB:151712, usedMB:109039
2022-01-25 08:29:10,302 INFO [core.PrepareCore] - took:17596, new shortcuts: 48 532 959, prepare|fastest|car-ors, dijkstras:2332771675, t(dijk):15897.85, t(period):10254.5, t(lazy):387.31, t(neighbor):5177.23, meanDegree:4, initSize:75706476, periodic:10, lazy:10, neighbor:90, totalMB:151712, usedMB:121751
2022-01-25 08:34:05,023 INFO [core.PrepareCore] - 57 252 984, updates:8, nodes: 14 313 248, shortcuts:26 574 942, dijkstras:1 737 613 125, t(dijk):14860.84, t(period):11620.55, t(lazy):0.0, t(neighbor):3258.48, meanDegree:2, algo:1092MB, totalMB:151712, usedMB:122044
2022-01-25 08:44:17,895 INFO [core.PrepareCore] - took:18503, new shortcuts: 60 549 516, prepare|shortest|car-ors, dijkstras:2990086202, t(dijk):16678.17, t(period):9270.76, t(lazy):602.01, t(neighbor):6937.22, meanDegree:7, initSize:75706476, periodic:10, lazy:10, neighbor:90, totalMB:151712, usedMB:120388
2022-01-25 08:55:48,557 INFO [core.PrepareCore] - took:17598, new shortcuts: 55 733 810, prepare|shortest|heavyvehicle, dijkstras:2669289509, t(dijk):15941.82, t(period):8890.06, t(lazy):540.57, t(neighbor):6576.98, meanDegree:8, initSize:71566232, periodic:10, lazy:10, neighbor:90, totalMB:151712, usedMB:132828
2022-01-25 09:31:14,930 INFO [core.PrepareCore] - took:19724, new shortcuts: 43 347 945, prepare|recommended|heavyvehicle, dijkstras:2057827286, t(dijk):18047.95, t(period):11907.5, t(lazy):375.42, t(neighbor):5497.82, meanDegree:4, initSize:71566232, periodic:10, lazy:10, neighbor:90, totalMB:151712, usedMB:86688
Exception in thread "pool-24-thread-4" 2022-01-25T19:23:04.711627504Z java.lang.ArrayIndexOutOfBoundsException: Index 1139 out of bounds for length 10932022-01-25T19:23:04.711637903Z 
    at com.graphhopper.storage.RAMIntDataAccess.getInt(RAMIntDataAccess.java:208)
    at com.graphhopper.storage.GHNodeAccess.getLatitude(GHNodeAccess.java:70)
    at org.heigit.ors.fastisochrones.partitioning.Projector.projIndividualValue(Projector.java:113)
    at org.heigit.ors.fastisochrones.partitioning.Projector.calculateProjectionOrder(Projector.java:97)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.graphBiSplit(InertialFlow.java:104)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.run(InertialFlow.java:82)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
Exception in thread "pool-24-thread-7" 2022-01-25T19:25:33.295748791Z Exception in thread "pool-24-thread-8" 2022-01-25T19:25:33.295766816Z java.lang.ArrayIndexOutOfBoundsException: Index 1103 out of bounds for length 1093
    at com.graphhopper.storage.RAMIntDataAccess.getInt(RAMIntDataAccess.java:208)
    at com.graphhopper.storage.GHNodeAccess.getLatitude(GHNodeAccess.java:70)
    at org.heigit.ors.fastisochrones.partitioning.Projector.projIndividualValue(Projector.java:115)2022-01-25T19:25:33.295874340Z 
    at org.heigit.ors.fastisochrones.partitioning.Projector.calculateProjectionOrder(Projector.java:97)2022-01-25T19:25:33.295880120Z 
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.graphBiSplit(InertialFlow.java:104)2022-01-25T19:25:33.295917311Z 
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.run(InertialFlow.java:82)2022-01-25T19:25:33.295924495Z 
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)2022-01-25T19:25:33.295930807Z 
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
java.lang.ArrayIndexOutOfBoundsException: Index 1114 out of bounds for length 1093
    at com.graphhopper.storage.RAMIntDataAccess.getInt(RAMIntDataAccess.java:208)
    at com.graphhopper.storage.GHNodeAccess.getLatitude(GHNodeAccess.java:70)
    at org.heigit.ors.fastisochrones.partitioning.Projector.projIndividualValue(Projector.java:113)
    at org.heigit.ors.fastisochrones.partitioning.Projector.calculateProjectionOrder(Projector.java:97)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.graphBiSplit(InertialFlow.java:104)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.run(InertialFlow.java:82)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
Exception in thread "pool-24-thread-11" 2022-01-25T19:40:42.145599911Z java.lang.ArrayIndexOutOfBoundsException: Index 1109 out of bounds for length 1093
    at com.graphhopper.storage.RAMIntDataAccess.getInt(RAMIntDataAccess.java:208)
    at com.graphhopper.storage.GHNodeAccess.getLatitude(GHNodeAccess.java:70)
    at org.heigit.ors.fastisochrones.partitioning.Projector.projIndividualValue(Projector.java:113)
    at org.heigit.ors.fastisochrones.partitioning.Projector.calculateProjectionOrder(Projector.java:97)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.graphBiSplit(InertialFlow.java:104)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.run(InertialFlow.java:82)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)2022-01-25T19:40:42.145648914Z 
    at java.base/java.lang.Thread.run(Thread.java:829)
Exception in thread "pool-24-thread-2" 2022-01-25T19:49:44.744611837Z java.lang.ArrayIndexOutOfBoundsException: Index 1113 out of bounds for length 1093
    at com.graphhopper.storage.RAMIntDataAccess.getInt(RAMIntDataAccess.java:208)
    at com.graphhopper.storage.GHNodeAccess.getLatitude(GHNodeAccess.java:70)
    at org.heigit.ors.fastisochrones.partitioning.Projector.projIndividualValue(Projector.java:113)
    at org.heigit.ors.fastisochrones.partitioning.Projector.calculateProjectionOrder(Projector.java:97)2022-01-25T19:49:44.744651022Z 
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.graphBiSplit(InertialFlow.java:104)
    at org.heigit.ors.fastisochrones.partitioning.InertialFlow.run(InertialFlow.java:82)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)2022-01-25T19:49:44.744659488Z 
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
Exception in thread "pool-24-thread-10" 2022-01-25T19:51:00.652898701Z Exception in thread "pool-24-thread-5" 2022-01-25T19:51:00.652957502Z java.lang.ArrayIndexOutOfBoundsException
java.lang.ArrayIndexOutOfBoundsException2022-01-25T19:51:00.653002438Z 
Exception in thread "pool-24-thread-12" java.lang.ArrayIndexOutOfBoundsException
Exception in thread "pool-24-thread-13" 2022-01-25T19:52:32.751517046Z java.lang.ArrayIndexOutOfBoundsException
Exception in thread "pool-24-thread-14" 2022-01-25T19:52:35.424695543Z java.lang.ArrayIndexOutOfBoundsException2022-01-25T19:52:35.424713366Z 
Exception in thread "pool-24-thread-3" java.lang.ArrayIndexOutOfBoundsException
Exception in thread "pool-24-thread-9" 2022-01-25T19:52:36.433344932Z java.lang.ArrayIndexOutOfBoundsException
Exception in thread "pool-24-thread-1" java.lang.ArrayIndexOutOfBoundsException2022-01-25T19:52:36.489459375Z 
Exception in thread "pool-24-thread-15" 2022-01-25T19:52:36.489721533Z java.lang.ArrayIndexOutOfBoundsException2022-01-25T19:52:36.489739797Z 
Exception in thread "pool-24-thread-20" 2022-01-25T19:52:36.603498568Z java.lang.ArrayIndexOutOfBoundsException
2022-01-26 00:22:57,232 INFO [routing.RoutingProfile] - [1] FlagEncoders: 1, bits used [UNKNOWN]/64.
2022-01-26 00:22:57,234 INFO [routing.RoutingProfile] - [1] Capacity: [UNKNOWN]. (edges - 90794987, nodes - 71566232)
2022-01-26 00:22:57,236 INFO [routing.RoutingProfile] - [1] Total time: 101270.689s.
2022-01-26 00:22:57,236 INFO [routing.RoutingProfile] - [1] Finished at: 2022-01-26 00:22:57.
2022-01-26 00:22:57,236 INFO [routing.RoutingProfile] -                               

Here's what I was expecting

I was expecting successful end of the process. I also tried the same config on smaller map: http://download.geofabrik.de/europe/poland-latest.osm.pbf. Do you think I should retry with more RAM? If so, could you help me with proper required resources estimation?

starzu-sentio commented 2 years ago

After another 24h I've got more logs with OOM:

java.lang.OutOfMemoryError: Java heap space
Dumping heap to /ors-core/data/java_pid132.hprof ...
OpenJDK 64-Bit Server VM warning: cannot dump array of type object[] with length 798381090; truncating to length 536870908
Heap dump file created [207702913082 bytes in 1905.527 secs]
Exception in thread "AsyncFileHandlerWriter-653687670" 2022-01-27T00:05:18.044902217Z java.lang.OutOfMemoryError: Java heap space
27-Jan-2022 00:05:18.044 SEVERE [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run Unexpected death of background thread [ContainerBackgroundProcessor[StandardEngine[Catalina]]]
    java.lang.OutOfMemoryError: Java heap space
        at java.base/java.net.URI.create(URI.java:881)
        at java.base/java.net.URI.resolve(URI.java:1066)
        at org.apache.tomcat.util.file.ConfigFileLoader.getURI(ConfigFileLoader.java:110)
        at org.apache.catalina.users.MemoryUserDatabase.backgroundProcess(MemoryUserDatabase.java:673)
        at org.apache.catalina.realm.UserDatabaseRealm.backgroundProcess(UserDatabaseRealm.java:138)
        at org.apache.catalina.realm.CombinedRealm.backgroundProcess(CombinedRealm.java:308)
        at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1158)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1398)
        at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1370)
        at java.base/java.lang.Thread.run(Thread.java:829)
Exception in thread "ContainerBackgroundProcessor[StandardEngine[Catalina]]" 2022-01-27T00:05:18.045890091Z java.lang.OutOfMemoryError: Java heap space
    at java.base/java.net.URI.create(URI.java:881)
    at java.base/java.net.URI.resolve(URI.java:1066)
    at org.apache.tomcat.util.file.ConfigFileLoader.getURI(ConfigFileLoader.java:110)
    at org.apache.catalina.users.MemoryUserDatabase.backgroundProcess(MemoryUserDatabase.java:673)
    at org.apache.catalina.realm.UserDatabaseRealm.backgroundProcess(UserDatabaseRealm.java:138)
    at org.apache.catalina.realm.CombinedRealm.backgroundProcess(CombinedRealm.java:308)2022-01-27T00:05:18.045932862Z 
    at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1158)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1398)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1370)2022-01-27T00:05:18.045958771Z 
    at java.base/java.lang.Thread.run(Thread.java:829)
27 Jan 00:05:18 ERROR [routing.RoutingProfileManager] - java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space
27 Jan 00:05:18 ERROR [routing.RoutingProfileManager] - Failed to initialize RoutingProfileManager instance.
java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space
    at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
    at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
    at org.heigit.ors.routing.RoutingProfileManager.initialize(RoutingProfileManager.java:178) ~[classes/:6.7.0]
    at org.heigit.ors.routing.RoutingProfileManager.getInstance(RoutingProfileManager.java:72) ~[classes/:6.7.0]
    at org.heigit.ors.servlet.listeners.ORSInitContextListener.lambda$contextInitialized$0(ORSInitContextListener.java:41) ~[classes/:6.7.0]
    at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.OutOfMemoryError: Java heap space
    at java.lang.Integer.valueOf(Integer.java:1059) ~[?:?]
    at org.opensphere.geometry.algorithm.ConcaveHullOpenSphere.concaveHull(ConcaveHullOpenSphere.java:260) ~[classes/:6.7.0]
    at org.opensphere.geometry.algorithm.ConcaveHullOpenSphere.getConcaveHull(ConcaveHullOpenSphere.java:169) ~[classes/:6.7.0]
    at org.heigit.ors.fastisochrones.Contour.concHullOfNodes(Contour.java:212) ~[classes/:6.7.0]
    at org.heigit.ors.fastisochrones.Contour.createContour(Contour.java:404) ~[classes/:6.7.0]
    at org.heigit.ors.fastisochrones.Contour.handleBaseCells(Contour.java:103) ~[classes/:6.7.0]
    at org.heigit.ors.fastisochrones.Contour.calculateContour(Contour.java:87) ~[classes/:6.7.0]
    at org.heigit.ors.routing.graphhopper.extensions.ORSGraphHopper.calculateContours(ORSGraphHopper.java:851) ~[classes/:6.7.0]
    at org.heigit.ors.routing.graphhopper.extensions.ORSGraphHopper.postProcessing(ORSGraphHopper.java:675) ~[classes/:6.7.0]
    at com.graphhopper.GraphHopper.process(GraphHopper.java:703) ~[graphhopper-core-v0.13.21.jar:?]
    at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:680) ~[graphhopper-core-v0.13.21.jar:?]
    at org.heigit.ors.routing.graphhopper.extensions.ORSGraphHopper.importOrLoad(ORSGraphHopper.java:163) ~[classes/:6.7.0]
    at org.heigit.ors.routing.RoutingProfile.initGraphHopper(RoutingProfile.java:184) ~[classes/:6.7.0]
    at org.heigit.ors.routing.RoutingProfile.<init>(RoutingProfile.java:128) ~[classes/:6.7.0]
    at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:35) ~[classes/:6.7.0]
    at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:21) ~[classes/:6.7.0]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
    ... 1 more
27 Jan 00:05:18 INFO [routing.RoutingProfileManager] - ====> Recycling garbage...
27 Jan 00:05:18 INFO [routing.RoutingProfileManager] - Before:  Total - 180 GB, Free - 78.01 GB, Max: 180 GB, Used - 101.99 GB
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - After:  Total - 113.75 GB, Free - 80.73 GB, Max: 180 GB, Used - 33.02 GB
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - ========================================================================
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - ====> Memory usage by profiles:
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - [1] 16.16 GB (48.9%)
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - Total: 16.16 GB (48.9%)
27 Jan 00:05:20 INFO [routing.RoutingProfileManager] - ========================================================================

It seems that memory limit is at least one of the problems.

HendrikLeuschner commented 2 years ago

Thanks for posting, will have a look at it. Memory requirements for Europe should be way below 100GB.

HendrikLeuschner commented 2 years ago

Hi @starzu-sentio the second error message you got was when you restarted from scratch with the same parameters?

starzu-sentio commented 2 years ago

No, it was hanging 24h as far as I remember.

tflabs-nl commented 2 years ago

Seeing a similar issue while importing latest europe from europe-latest.osm.bpf

Using the docker image:

09 Feb 17:36:22 ERROR [routing.RoutingProfileManager] - java.util.concurrent.ExecutionException: java.lang.RuntimeException: Couldn't process file data/osm_file.pbf, error: Index -1 out of bounds for length 4725
09 Feb 17:36:22 ERROR [routing.RoutingProfileManager] - Failed to initialize RoutingProfileManager instance.
java.util.concurrent.ExecutionException: java.lang.RuntimeException: Couldn't process file data/osm_file.pbf, error: Index -1 out of bounds for length 4725
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.heigit.ors.routing.RoutingProfileManager.initialize(RoutingProfileManager.java:176) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfileManager.getInstance(RoutingProfileManager.java:70) ~[classes/:6.6.1]
at org.heigit.ors.servlet.listeners.ORSInitContextListener.lambda$contextInitialized$0(ORSInitContextListener.java:41) ~[classes/:6.6.1]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.lang.RuntimeException: Couldn't process file data/osm_file.pbf, error: Index -1 out of bounds for length 4725
at com.graphhopper.reader.osm.OSMReader.writeOsm2Graph(OSMReader.java:326) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.reader.osm.OSMReader.readGraph(OSMReader.java:178) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.importData(GraphHopper.java:735) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.readData(GraphHopper.java:714) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.process(GraphHopper.java:701) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:680) ~[graphhopper-core-v0.13.15.jar:?]
at org.heigit.ors.routing.graphhopper.extensions.ORSGraphHopper.importOrLoad(ORSGraphHopper.java:155) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfile.initGraphHopper(RoutingProfile.java:189) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfile.<init>(RoutingProfile.java:133) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:35) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:21) ~[classes/:6.6.1]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
... 1 more
Caused by: java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 4725
at com.graphhopper.storage.RAMDataAccess.getInt(RAMDataAccess.java:207) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.reader.PillarInfo.getLatitude(PillarInfo.java:83) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.reader.osm.OSMReader.handlePillarNode(OSMReader.java:946) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.reader.osm.OSMReader.addOSMWay(OSMReader.java:830) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.reader.osm.OSMReader.processWay(OSMReader.java:440) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at org.heigit.ors.routing.graphhopper.extensions.ORSOSMReader.processWay(ORSOSMReader.java:165) ~[classes/:6.6.1]
at com.graphhopper.reader.osm.OSMReader.writeOsm2Graph(OSMReader.java:302) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.reader.osm.OSMReader.readGraph(OSMReader.java:178) ~[graphhopper-reader-osm-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.importData(GraphHopper.java:735) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.readData(GraphHopper.java:714) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.process(GraphHopper.java:701) ~[graphhopper-core-v0.13.15.jar:?]
at com.graphhopper.GraphHopper.importOrLoad(GraphHopper.java:680) ~[graphhopper-core-v0.13.15.jar:?]
at org.heigit.ors.routing.graphhopper.extensions.ORSGraphHopper.importOrLoad(ORSGraphHopper.java:155) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfile.initGraphHopper(RoutingProfile.java:189) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfile.<init>(RoutingProfile.java:133) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:35) ~[classes/:6.6.1]
at org.heigit.ors.routing.RoutingProfileLoader.call(RoutingProfileLoader.java:21) ~[classes/:6.6.1]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
... 1 more
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - ====> Recycling garbage...
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - Before: Total - 115 GB, Free - 71.31 GB, Max: 115 GB, Used - 43.69 GB
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - After: Total - 115 GB, Free - 114.95 GB, Max: 115 GB, Used - 55.45 MB
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - ========================================================================
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - ====> Memory usage by profiles:
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - Total: 0 B (0.0%)
09 Feb 17:36:22 INFO [routing.RoutingProfileManager] - ========================================================================
HendrikLeuschner commented 2 years ago

@tflabs-nl this looks like a different issue. It happens within the OSMReader. Best to open a new issue.

tflabs-nl commented 2 years ago

@HendrikLeuschner I see now, thank you! Will try to re-download the pbf before opening a separate issue to make sure the pbf itself isn't the issue.

starzu-sentio commented 2 years ago

@HendrikLeuschner Did you find anything?