Required memory higher than actual usage?

openrouteservice
1

Hello,

I’ve been working with a local ORS client for a few months without problems now. I used to just allocate a sufficient amount of memory to the docker container to not run into any problems.
Currently, I am trying to automate the setup process. To prevent allocating too much memory for systems that can just barely process certain OSM extracts, I am trying to accurately determine the needed memory for the setup.

After reading a lot of questions on this forum and studying the documentation, I was of the impression that multiplying the extract size by 2.5 and then again by the number of profiles should easily be enough memory. However, I need about 1.5 GB of allocated memory to run the service with 1 profile and an extract of 71 MB in size. With anything less than that, I get an OutOfMemoryError thrown at me. This is happening on the first docker image build and I also disabled the deletion of all other profiles than car in the Dockerfile, so I’m pretty sure that the service should only build the profiles specificed in my custom config file.

The following docker-compose-yml and logs are from an attempt of setting a container up with a fresh download, 1 GB of allocated RAM, 1 profile (car) and a 71 MB extract. The setup seems to run into an OutOfMemoryError within 7 seconds (so before even starting to build the graphs I suppose?).

version: '2.4'
services:
  ors-app:
    container_name: ors-app
    ports:
      - 8080:8080
      - 9001:9001
    image: openrouteservice/openrouteservice:latest
    build:
      context: ../
      args:
        ORS_CONFIG: ./docker/data/ors-config-sample.json
        OSM_FILE: ./docker/data/bbbike_Koeln.osm.pbf
    user: "${ORS_UID:-0}:${ORS_GID:-0}"
    volumes:
      - ./graphs:/ors-core/data/graphs
      - ./elevation_cache:/ors-core/data/elevation_cache
      - ./logs/ors:/var/log/ors
      - ./logs/tomcat:/usr/local/tomcat/logs
      - ./conf:/ors-conf
      #- ./your_osm.pbf:/ors-core/data/osm_file.pbf
    environment:
      - BUILD_GRAPHS=True  # Forces the container to rebuild the graphs, e.g. when PBF is changed
      - "JAVA_OPTS=-Djava.awt.headless=true -server -XX:TargetSurvivorRatio=75 -XX:SurvivorRatio=64 -XX:MaxTenuringThreshold=3 -XX:+UseG1GC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=4 -Xms1g -Xmx1g"
      - "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"

### openrouteservice configuration ###
No ors-config.json in ors-conf folder. Copy config from /ors-core/openrouteservice/src/main/resources/ors-config.json
### Package openrouteservice and deploy to Tomcat ###
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/usr/share/maven/lib/guice.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
29-Jul-2021 11:36:36.053 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.5.39
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Mar 14 2019 11:24:26 UTC
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.5.39.0
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            5.4.72-microsoft-standard-WSL2
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
29-Jul-2021 11:36:36.055 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
29-Jul-2021 11:36:36.056 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.12+7
29-Jul-2021 11:36:36.056 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
29-Jul-2021 11:36:36.056 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
29-Jul-2021 11:36:36.056 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
29-Jul-2021 11:36:36.057 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
29-Jul-2021 11:36:36.057 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
29-Jul-2021 11:36:36.057 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
29-Jul-2021 11:36:36.057 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.awt.headless=true
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:TargetSurvivorRatio=75
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:SurvivorRatio=64
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:MaxTenuringThreshold=3
29-Jul-2021 11:36:36.058 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+UseG1GC
29-Jul-2021 11:36:36.059 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:+ScavengeBeforeFullGC
29-Jul-2021 11:36:36.059 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -XX:ParallelGCThreads=4
29-Jul-2021 11:36:36.059 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms1g
29-Jul-2021 11:36:36.059 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx1g
29-Jul-2021 11:36:36.059 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.port=9001
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.rmi.port=9001
29-Jul-2021 11:36:36.060 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.authenticate=false
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.management.jmxremote.ssl=false
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.rmi.server.hostname=localhost
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
29-Jul-2021 11:36:36.061 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
29-Jul-2021 11:36:36.062 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib]
29-Jul-2021 11:36:36.092 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
29-Jul-2021 11:36:36.103 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
29-Jul-2021 11:36:36.113 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
29-Jul-2021 11:36:36.114 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
29-Jul-2021 11:36:36.115 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 322 ms
29-Jul-2021 11:36:36.164 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
29-Jul-2021 11:36:36.164 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.39
29-Jul-2021 11:36:36.193 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/ors.war]
11:36:40.165 [localhost-startStop-1] INFO  org.heigit.ors.config.AppConfig - Default path of 'ors-config.json' used for configuration
11:36:40.171 [localhost-startStop-1] INFO  org.heigit.ors.config.AppConfig - Loading configuration from /usr/local/tomcat/webapps/ors/WEB-INF/classes/ors-config.json

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.5.RELEASE)

29 Jul 11:36:40 INFO [ors.Application] - Starting Application v6.6.1 on 8205b4e343b5 with PID 151 (/usr/local/tomcat/webapps/ors/WEB-INF/classes started by root in /ors-core)
29 Jul 11:36:40 DEBUG [ors.Application] - Running with Spring Boot v2.3.5.RELEASE, Spring v5.2.10.RELEASE
29 Jul 11:36:40 INFO [ors.Application] - No active profile set, falling back to default profiles: default
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
29 Jul 11:36:43 INFO [ors.Application] - Started Application in 3.097 seconds (JVM running for 7.677)
29-Jul-2021 11:36:43.121 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
<?xml version="1.0" ?>
<Configuration>
  <Properties>
    <Property name="filename">/var/log/ors/ors-logs.log</Property>
  </Properties>
</Configuration>
29 Jul 11:36:43 INFO [routing.RoutingProfileManager] -  Total - 1024 MB, Free - 761.82 MB, Max: 1024 MB, Used - 262.18 MB
29 Jul 11:36:43 INFO [routing.RoutingProfileManager] -
29-Jul-2021 11:36:43.172 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/ors.war] has finished in [6,979] ms
29-Jul-2021 11:36:43.174 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
29 Jul 11:36:43 INFO [routing.RoutingProfileManager] - ====> Initializing profiles from 'data/osm_file.pbf' (1 threads) ...
29 Jul 11:36:43 INFO [routing.RoutingProfileManager] -
29 Jul 11:36:43 INFO [routing.RoutingProfileManager] -
29-Jul-2021 11:36:43.197 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [23] ms
29-Jul-2021 11:36:43.197 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/examples]
29 Jul 11:36:43 INFO [routing.RoutingProfile] - [1] Profiles: 'driving-car', location: 'data/graphs/car'.
29-Jul-2021 11:36:43.316 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/examples] has finished in [118] ms
29-Jul-2021 11:36:43.316 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
29-Jul-2021 11:36:43.329 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [13] ms
29-Jul-2021 11:36:43.329 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/ROOT]
29-Jul-2021 11:36:43.341 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/ROOT] has finished in [12] ms
29-Jul-2021 11:36:43.341 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/host-manager]
29-Jul-2021 11:36:43.357 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/host-manager] has finished in [16] ms
29-Jul-2021 11:36:43.366 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
29-Jul-2021 11:36:43.375 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
29-Jul-2021 11:36:43.392 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 7276 ms
Exception in thread "pool-11-thread-2" java.lang.OutOfMemoryError: Java heap space
        at java.base/java.util.Arrays.copyOf(Arrays.java:3689)
        at java.base/java.util.ArrayList.grow(ArrayList.java:238)
        at java.base/java.util.ArrayList.grow(ArrayList.java:243)
        at java.base/java.util.ArrayList.add(ArrayList.java:486)
        at java.base/java.util.ArrayList.add(ArrayList.java:499)
        at com.graphhopper.reader.osm.pbf.PbfBlobDecoder.processNodes(PbfBlobDecoder.java:286)
        at com.graphhopper.reader.osm.pbf.PbfBlobDecoder.processOsmPrimitives(PbfBlobDecoder.java:374)
        at com.graphhopper.reader.osm.pbf.PbfBlobDecoder.runAndTrapExceptions(PbfBlobDecoder.java:388)
        at com.graphhopper.reader.osm.pbf.PbfBlobDecoder.run(PbfBlobDecoder.java:400)
        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)

Ramping this up to 1.5 GB without changing anything else succeeds. However, if I understand correctly, it uses up 1.17 GBs of RAM and then only uses 164 MBs after garbage recycling.

version: '2.4'
services:
  ors-app:
    container_name: ors-app
    ports:
      - 8080:8080
      - 9001:9001
    image: openrouteservice/openrouteservice:latest
    build:
      context: ../
      args:
        ORS_CONFIG: ./docker/data/ors-config-sample.json
        OSM_FILE: ./docker/data/bbbike_Koeln.osm.pbf
    user: "${ORS_UID:-0}:${ORS_GID:-0}"
    volumes:
      - ./graphs:/ors-core/data/graphs
      - ./elevation_cache:/ors-core/data/elevation_cache
      - ./logs/ors:/var/log/ors
      - ./logs/tomcat:/usr/local/tomcat/logs
      - ./conf:/ors-conf
      #- ./your_osm.pbf:/ors-core/data/osm_file.pbf
    environment:
      - BUILD_GRAPHS=True  # Forces the container to rebuild the graphs, e.g. when PBF is changed
      - "JAVA_OPTS=-Djava.awt.headless=true -server -XX:TargetSurvivorRatio=75 -XX:SurvivorRatio=64 -XX:MaxTenuringThreshold=3 -XX:+UseG1GC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=4 -Xms1500m -Xmx1500m"
      - "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"

... (cut off due to character limit)

29 Jul 11:49:47 INFO [ors.Application] - Starting Application v6.6.1 on e3449661808b with PID 144 (/usr/local/tomcat/webapps/ors/WEB-INF/classes started by root in /ors-core)
29 Jul 11:49:47 DEBUG [ors.Application] - Running with Spring Boot v2.3.5.RELEASE, Spring v5.2.10.RELEASE
29 Jul 11:49:47 INFO [ors.Application] - No active profile set, falling back to default profiles: default
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
29 Jul 11:49:49 INFO [ors.Application] - Started Application in 3.131 seconds (JVM running for 7.356)
29-Jul-2021 11:49:49.674 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
<?xml version="1.0" ?>
<Configuration>
  <Properties>
    <Property name="filename">/var/log/ors/ors-logs.log</Property>
  </Properties>
</Configuration>
29-Jul-2021 11:49:49.719 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/ors.war] has finished in [6,677] ms
29-Jul-2021 11:49:49.720 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
29 Jul 11:49:49 INFO [routing.RoutingProfileManager] -  Total - 1.46 GB, Free - 1.21 GB, Max: 1.46 GB, Used - 264.69 MB
29 Jul 11:49:49 INFO [routing.RoutingProfileManager] -
29-Jul-2021 11:49:49.743 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [23] ms
29-Jul-2021 11:49:49.744 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/examples]
29 Jul 11:49:49 INFO [routing.RoutingProfileManager] - ====> Initializing profiles from 'data/osm_file.pbf' (1 threads) ...
29 Jul 11:49:49 INFO [routing.RoutingProfileManager] -
29 Jul 11:49:49 INFO [routing.RoutingProfileManager] -
29 Jul 11:49:49 INFO [routing.RoutingProfile] - [1] Profiles: 'driving-car', location: 'data/graphs/car'.
29-Jul-2021 11:49:49.864 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/examples] has finished in [120] ms
29-Jul-2021 11:49:49.864 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
29-Jul-2021 11:49:49.876 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [12] ms
29-Jul-2021 11:49:49.877 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/ROOT]
29-Jul-2021 11:49:49.889 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/ROOT] has finished in [12] ms
29-Jul-2021 11:49:49.890 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/host-manager]
29-Jul-2021 11:49:49.904 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/host-manager] has finished in [14] ms
29-Jul-2021 11:49:49.911 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
29-Jul-2021 11:49:49.927 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
29-Jul-2021 11:49:49.939 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 6977 ms
29 Jul 11:50:51 INFO [core.PrepareCore] - 0, updates:0, nodes: 199 365, shortcuts:0, dijkstras:672 644, t(dijk):0.39, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:3MB, totalMB:1500, usedMB:459
29 Jul 11:50:54 INFO [core.PrepareCore] - 39 873, updates:1, nodes: 159 492, shortcuts:282, dijkstras:1 349 437, t(dijk):3.5, t(period):2.8, t(lazy):0.0, t(neighbor):0.57, meanDegree:1, algo:3MB, totalMB:1500, usedMB:475
29 Jul 11:50:59 INFO [core.PrepareCore] - 79 746, updates:3, nodes: 119 619, shortcuts:294, dijkstras:2 333 832, t(dijk):8.0, t(period):7.35, t(lazy):0.0, t(neighbor):0.94, meanDegree:1, algo:3MB, totalMB:1500, usedMB:496
29 Jul 11:51:04 INFO [core.PrepareCore] - 119 619, updates:5, nodes: 79 746, shortcuts:28 642, dijkstras:3 228 570, t(dijk):12.6, t(period):10.83, t(lazy):0.0, t(neighbor):2.16, meanDegree:2, algo:3MB, totalMB:1500, usedMB:522
29 Jul 11:51:09 INFO [core.PrepareCore] - 159 492, updates:7, nodes: 39 873, shortcuts:65 069, dijkstras:4 024 207, t(dijk):16.73, t(period):13.17, t(lazy):0.0, t(neighbor):3.89, meanDegree:2, algo:3MB, totalMB:1500, usedMB:547
29 Jul 11:51:13 INFO [core.PrepareCore] - took:22, new shortcuts: 107 231, prepare|fastest|car-ors, dijkstras:4840958, t(dijk):20.06, t(period):14.08, t(lazy):0.33, t(neighbor):5.92, meanDegree:4, initSize:199365, periodic:10, lazy:10, neighbor:90, totalMB:1500, usedMB:568
29 Jul 11:51:13 INFO [core.PrepareCore] - 0, updates:0, nodes: 199 365, shortcuts:0, dijkstras:672 644, t(dijk):0.34, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:3MB, totalMB:1500, usedMB:588
29 Jul 11:51:16 INFO [core.PrepareCore] - 39 873, updates:1, nodes: 159 492, shortcuts:215, dijkstras:1 345 445, t(dijk):2.87, t(period):2.3, t(lazy):0.0, t(neighbor):0.46, meanDegree:1, algo:3MB, totalMB:1500, usedMB:602
29 Jul 11:51:20 INFO [core.PrepareCore] - 79 746, updates:3, nodes: 119 619, shortcuts:227, dijkstras:2 340 893, t(dijk):6.6, t(period):6.12, t(lazy):0.0, t(neighbor):0.77, meanDegree:1, algo:3MB, totalMB:1500, usedMB:623
29 Jul 11:51:25 INFO [core.PrepareCore] - 119 619, updates:5, nodes: 79 746, shortcuts:30 720, dijkstras:3 266 083, t(dijk):10.61, t(period):9.17, t(lazy):0.0, t(neighbor):1.87, meanDegree:1, algo:3MB, totalMB:1500, usedMB:650
29 Jul 11:51:29 INFO [core.PrepareCore] - 159 492, updates:7, nodes: 39 873, shortcuts:68 104, dijkstras:4 108 726, t(dijk):14.19, t(period):11.33, t(lazy):0.0, t(neighbor):3.34, meanDegree:2, algo:3MB, totalMB:1500, usedMB:675
29 Jul 11:51:34 INFO [core.PrepareCore] - took:21, new shortcuts: 122 236, prepare|shortest|car-ors, dijkstras:5407480, t(dijk):18.36, t(period):12.25, t(lazy):0.41, t(neighbor):6.16, meanDegree:5, initSize:199365, periodic:10, lazy:10, neighbor:90, totalMB:1500, usedMB:699
29 Jul 11:51:54 INFO [routing.RoutingProfile] - [1] FlagEncoders: 1, bits used [UNKNOWN]/64.
29 Jul 11:51:54 INFO [routing.RoutingProfile] - [1] Capacity: [UNKNOWN]. (edges - 254544, nodes - 199365)
29 Jul 11:51:54 INFO [routing.RoutingProfile] - [1] Total time: 124.846s.
29 Jul 11:51:54 INFO [routing.RoutingProfile] - [1] Finished at: 2021-07-29 11:51:54.
29 Jul 11:51:54 INFO [routing.RoutingProfile] -
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - Total time: 124.893s.
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - ========================================================================
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - ====> Recycling garbage...
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - Before:  Total - 1.46 GB, Free - 302.36 MB, Max: 1.46 GB, Used - 1.17 GB
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - After:  Total - 1.46 GB, Free - 1.30 GB, Max: 1.46 GB, Used - 164.06 MB
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - ========================================================================
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - ====> Memory usage by profiles:
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - [1] 54.03 MB (32.9%)
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - Total: 54.03 MB (32.9%)
29 Jul 11:51:54 INFO [routing.RoutingProfileManager] - ========================================================================

It gets even more confusing to me when I activate another profile. The graphs won’t build until I allocate around 2 GBs. However, according to the logs, 580 MBs are used before garbage recycling and 336 MBs after.
So, why does such a tiny extract need over 16 times its size in memory usage to build just 1 profile? Isn’t it supposed to need around 2-3 times its size as memory? Why does activating a second profile reduce the required amount of RAM? Am I misunderstanding the log memory info?

Thanks!

2

hi @JsLth

that definitely is a bit strange as can build with a 170MB file with 1GB heap without any issues… is there anyway for you to share the app.config you are using and the dataset?

The details about the memory consumption in the logs can sometimes be a bit off due to how Java and Docker cooperate with each other, so I wouldn’t take those as gospel.

3

Hey @adam

I was using the prepared bbbike pbf from OSM exports for Koeln by BBBike.org. However, you inspired me to try a different extract, so I used the pbf from Geofabrik Download Server. I allocated 500 MB to build this one and it worked seamlessly. So it seems to be a problem with the bbbike extract.

Is there anything to keep in mind when deciding for an extract source?

Also, I only changed the active profiles in the config file and the deletion settings in the Dockerfile. Everything else is from yesterday’s source version. If it’s still of use for you, here is the config file:

{
  "ors": {
    "info": {
      "base_url": "https://openrouteservice.org/",
      "support_mail": "support@openrouteservice.org",
      "author_tag": "openrouteservice",
      "content_licence": "LGPL 3.0"
    },
    "services": {
      "matrix": {
        "enabled": true,
        "maximum_routes": 100,
        "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": 100000
          }
        ],
        "maximum_range_time": [
          {
            "profiles": "any",
            "value": 18000
          },
          {
            "profiles": "driving-car, driving-hgv",
            "value": 3600
          }
        ],
        "fastisochrones": {
          "maximum_range_distance": [
            {
              "profiles": "any",
              "value": 50000
            },
            {
              "profiles": "driving-car, driving-hgv",
              "value": 500000
            }
          ],
          "maximum_range_time": [
            {
              "profiles": "any",
              "value": 18000
            },
            {
              "profiles": "driving-car, driving-hgv",
              "value": 10800
            }
          ],
          "profiles": {
            "default_params": {
              "enabled": false,
              "threads": 12,
              "weightings": "recommended",
              "maxcellnodes": 5000
            },
            "profile-hgv": {
              "enabled": true,
              "threads": 12,
              "weightings": "recommended, shortest",
              "maxcellnodes": 5000
            }
          }
        },
        "maximum_intervals": 10,
        "maximum_locations": 2,
        "allow_compute_area": true
      },
      "routing": {
        "enabled": true,
        "mode": "normal",
        "routing_description": "This is a routing file from openrouteservice",
        "routing_name": "openrouteservice routing",
        "sources": [
          "openrouteservice/src/main/files/heidelberg.osm.gz"
        ],
        "init_threads": 2,
        "attribution": "openrouteservice.org, OpenStreetMap contributors",
        "elevation_preprocessed": false,
        "profiles": {
          "active": [
            "car"
          ],
          "default_params": {
            "encoder_flags_size": 8,
            "graphs_root_path": "graphs",
            "elevation_provider": "multi",
            "elevation_cache_path": "cgiar_provider",
            "elevation_cache_clear": false,
            "instructions": true,
            "maximum_distance": 100000,
            "maximum_distance_dynamic_weights": 100000,
            "maximum_distance_avoid_areas": 100000,
            "maximum_waypoints": 50,
            "maximum_snapping_radius": 400,
            "maximum_avoid_polygon_area": 200000000,
            "maximum_avoid_polygon_extent": 20000,
            "maximum_distance_alternative_routes": 100000,
            "maximum_alternative_routes": 3,
            "maximum_distance_round_trip_routes": 100000,
            "maximum_speed_lower_bound": 80,
            "preparation": {
              "min_network_size": 200,
              "min_one_way_network_size": 200,
              "methods": {
                "lm": {
                  "enabled": true,
                  "threads": 1,
                  "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": 100000,
              "elevation": true,
              "maximum_snapping_radius": 350,
              "preparation": {
                "min_network_size": 200,
                "min_one_way_network_size": 200,
                "methods": {
                  "ch": {
                    "enabled": true,
                    "threads": 1,
                    "weightings": "fastest"
                  },
                  "lm": {
                    "enabled": false,
                    "threads": 1,
                    "weightings": "fastest,shortest",
                    "landmarks": 16
                  },
                  "core": {
                    "enabled": true,
                    "threads": 1,
                    "weightings": "fastest,shortest",
                    "landmarks": 64,
                    "lmsets": "highways;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": 100000,
              "elevation": true,
              "preparation": {
                "min_network_size": 200,
                "min_one_way_network_size": 200,
                "methods": {
                  "ch": {
                    "enabled": true,
                    "threads": 1,
                    "weightings": "recommended"
                  },
                  "core": {
                    "enabled": true,
                    "threads": 1,
                    "weightings": "recommended,shortest",
                    "landmarks": 64,
                    "lmsets": "highways;allow_all"
                  }
                }
              },
              "execution": {
                "methods": {
                  "ch": {
                    "disabling_allowed": true
                  },
                  "core": {
                    "disabling_allowed": true,
                    "active_landmarks": 6
                  }
                }
              },
              "ext_storages": {
                "WayCategory": {},
                "HeavyVehicle": {
                  "restrictions": true
                },
                "WaySurfaceType": {}
              }
            }
          },
          "profile-bike-regular": {
            "profiles": "cycling-regular",
            "parameters": {
              "encoder_options": "consider_elevation=true|turn_costs=true|block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-bike-mountain": {
            "profiles": "cycling-mountain",
            "parameters": {
              "encoder_options": "consider_elevation=true|turn_costs=true|block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-bike-road": {
            "profiles": "cycling-road",
            "parameters": {
              "encoder_options": "consider_elevation=true|turn_costs=true|block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-bike-electric": {
            "profiles": "cycling-electric",
            "parameters": {
              "encoder_options": "consider_elevation=true|turn_costs=true|block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-walking": {
            "profiles": "foot-walking",
            "parameters": {
              "encoder_options": "block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-hiking": {
            "profiles": "foot-hiking",
            "parameters": {
              "encoder_options": "block_fords=false",
              "elevation": true,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "HillIndex": {},
                "TrailDifficulty": {}
              }
            }
          },
          "profile-wheelchair": {
            "profiles": "wheelchair",
            "parameters": {
              "encoder_options": "block_fords=true",
              "elevation": true,
              "maximum_snapping_radius": 50,
              "ext_storages": {
                "WayCategory": {},
                "WaySurfaceType": {},
                "Wheelchair": {
                  "KerbsOnCrossings": "true"
                },
                "OsmId": {}
              }
            }
          }
        }
      }
    },
    "logging": {
      "enabled": true,
      "level_file": "DEBUG_LOGGING.json",
      "location": "/var/log/ors",
      "stdout": true
    },
    "system_message": [
      {
        "active": false,
        "text": "This message would be sent with every routing bike fastest request",
        "condition": {
          "request_service": "routing",
          "request_profile": "cycling-regular,cycling-mountain,cycling-road,cycling-electric",
          "request_preference": "fastest"
        }
      },
      {
        "active": false,
        "text": "This message would be sent with every request for geojson response",
        "condition": {
          "api_format": "geojson"
        }
      },
      {
        "active": false,
        "text": "This message would be sent with every request on API v1 from January 2020 until June 2050",
        "condition": {
          "api_version": 1,
          "time_after": "2020-01-01T00:00:00Z",
          "time_before": "2050-06-01T00:00:00Z"
        }
      },
      {
        "active": false,
        "text": "This message would be sent with every request"
      }
    ]
  }
}
4

Great that you got it working. As a sanity check for you though, I also tried with the bbbkike extract and got the same “out of memory” error, so I guess there is some sort of circular loop in the dataset that causes data to be constantly re-read into memory.

in terms of data extract sources, there are no particular things that I can say to look out for. Generally I use geofabrik and then osmosis to extract relevant information or to clip the area if needed