Better graph build progress (or an reliable one)

[JPBM135]

Is there an existing issue for this?

• I have searched the existing issues

Feature/Enhancement Proposal

Although the progress of graph building takes time, it would be nice if we could get reliable progress, when I'm building with small files for test the logs from the RoutingProfileManager and core.PrepareCore pops up on my docker setup, but when I'm building for production they do not!

I tried a lot configurations and still couldn`t get the log to show up on my server!

Additional context

Solutions I tried

In config options

logging:
  file:
    name: ./logs/ors.log
  pattern:
    console: "%d{yyyy-MM-dd HH:mm:ss} %highlight{%-7p} %style{%50t}{Cyan} %style{[ %-40.40c{1.} ]}{Bright Cyan}   %m%n"
    file: "%d{yyyy-MM-dd HH:mm:ss} %p [%-40.40c{1.}] - %m%n"
  level:
    root: DEBUG
    org.heigit: DEBUG
    org.apache: DEBUG
    com.graphhopper: DEBUG
    springfox.documentation: DEBUG
    io.micrometer: DEBUG

Messing with the JAVA_OPTS

      - "JAVA_OPTS=-Djava.awt.headless=true -server -XX:TargetSurvivorRatio=75 -XX:SurvivorRatio=64 -XX:MaxTenuringThreshold=3 -XX:+UseG1GC -XX:+ScavengeBeforeFullGC -XX:ParallelGCThreads=4 -Xms24g -Xmx28g -Dorg.apache.logging.log4j.simplelog.StatusLogger.level=info -Dlogging.level.org.springframework=INFO -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=1044 -Dlog4j.debug=true -Dlog4j.configurationFile=file:/home/ors/ors-conf/log4j.properties"
      - "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 -Dorg.apache.logging.log4j.simplelog.StatusLogger.level=info"

I tried setting the logs from info to debug, even trace, I tried overriding the log4j file with this one:

# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1

# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%d{dd MMM HH:mm:ss} %p [%c{2}] - %m%n

log4j.logger.org.heigit=INFO
log4j.logger.org.apache=INFO
log4j.logger.com.graphhopper=INFO
log4j.logger.springfox.documentation=INFO
log4j.logger.io.micrometer=INFO

Still, I couldn`t get a reliable log source for the graphs' progress!

Logs example

Source: https://ask.openrouteservice.org/t/unable-to-find-walking-route-on-local-server/3185/3

2021-10-01 07:05:02,391 INFO [ors.Application] - Starting Application v6.6.1 on 04e58f76333a with PID 122 (/usr/local/tomcat/webapps/ors/WEB-INF/classes started by root in /ors-core)
2021-10-01 07:05:02,454 DEBUG [ors.Application] - Running with Spring Boot v2.3.5.RELEASE, Spring v5.2.10.RELEASE
2021-10-01 07:05:02,459 INFO [ors.Application] - No active profile set, falling back to default profiles: default
2021-10-01 07:05:07,709 INFO [ors.Application] - Started Application in 7.079 seconds (JVM running for 15.675)
2021-10-01 07:05:08,011 INFO [routing.RoutingProfileManager] -  Total - 1.00 GB, Free - 791.07 MB, Max: 2 GB, Used - 234.93 MB
2021-10-01 07:05:08,019 INFO [routing.RoutingProfileManager] -       
2021-10-01 07:05:08,176 INFO [routing.RoutingProfileManager] - ====> Initializing profiles from 'data/osm_file.pbf' (1 threads) ...
2021-10-01 07:05:08,183 INFO [routing.RoutingProfileManager] -                               
2021-10-01 07:05:08,208 INFO [routing.RoutingProfileManager] -                
2021-10-01 07:05:08,315 INFO [routing.RoutingProfile] - [1] Profiles: 'driving-car', location: 'data/graphs/car'.
2021-10-01 07:15:21,914 INFO [core.PrepareCore] - 0, updates:0, nodes: 902 218, shortcuts:0, dijkstras:3 215 591, t(dijk):31.69, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1242
2021-10-01 07:17:55,128 INFO [core.PrepareCore] - 180 444, updates:2, nodes: 721 774, shortcuts:2 491, dijkstras:8 893 934, t(dijk):126.35, t(period):137.73, t(lazy):0.0, t(neighbor):11.88, meanDegree:1, algo:13MB, totalMB:1725, usedMB:934
2021-10-01 07:19:55,685 INFO [core.PrepareCore] - 360 888, updates:4, nodes: 541 330, shortcuts:50 650, dijkstras:13 346 352, t(dijk):200.2, t(period):240.15, t(lazy):0.0, t(neighbor):25.86, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1032
2021-10-01 07:22:13,375 INFO [core.PrepareCore] - 541 332, updates:6, nodes: 360 886, shortcuts:250 931, dijkstras:18 126 817, t(dijk):284.32, t(period):317.74, t(lazy):0.0, t(neighbor):70.94, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1167
2021-10-01 07:24:12,763 INFO [core.PrepareCore] - 721 776, updates:8, nodes: 180 442, shortcuts:439 648, dijkstras:22 109 841, t(dijk):356.1, t(period):368.82, t(lazy):0.0, t(neighbor):123.28, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1282
2021-10-01 07:26:54,483 INFO [core.PrepareCore] - took:757, new shortcuts: 715 026, prepare|fastest|car-ors, dijkstras:28258853, t(dijk):451.13, t(period):378.67, t(lazy):15.18, t(neighbor):235.69, meanDegree:5, initSize:902218, periodic:10, lazy:10, neighbor:90, totalMB:1725, usedMB:984
2021-10-01 07:27:55,112 INFO [core.PrepareCore] - 0, updates:0, nodes: 902 218, shortcuts:0, dijkstras:3 215 591, t(dijk):30.32, t(period):0.0, t(lazy):0.0, t(neighbor):0.0, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1062
2021-10-01 07:30:18,816 INFO [core.PrepareCore] - 180 444, updates:2, nodes: 721 774, shortcuts:1 989, dijkstras:8 905 546, t(dijk):116.72, t(period):131.06, t(lazy):0.0, t(neighbor):10.14, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1188
2021-10-01 07:32:24,763 INFO [core.PrepareCore] - 360 888, updates:4, nodes: 541 330, shortcuts:66 919, dijkstras:13 575 639, t(dijk):192.39, t(period):236.82, t(lazy):0.0, t(neighbor):25.82, meanDegree:1, algo:13MB, totalMB:1725, usedMB:1292
2021-10-01 07:34:52,365 INFO [core.PrepareCore] - 541 332, updates:6, nodes: 360 886, shortcuts:265 829, dijkstras:18 634 930, t(dijk):280.78, t(period):324.27, t(lazy):0.0, t(neighbor):71.75, meanDegree:1, algo:13MB, totalMB:1725, usedMB:989
2021-10-01 07:37:15,919 INFO [core.PrepareCore] - 721 776, updates:8, nodes: 180 442, shortcuts:497 702, dijkstras:23 678 553, t(dijk):365.37, t(period):382.19, t(lazy):0.0, t(neighbor):138.87, meanDegree:2, algo:13MB, totalMB:1725, usedMB:1115
2021-10-01 07:43:50,761 INFO [core.PrepareCore] - took:1017, new shortcuts: 893 993, prepare|shortest|car-ors, dijkstras:39353408, t(dijk):604.28, t(period):400.25, t(lazy):34.75, t(neighbor):441.64, meanDegree:8, initSize:902218, periodic:10, lazy:10, neighbor:90, totalMB:1725, usedMB:1276
2021-10-01 07:47:49,313 INFO [routing.RoutingProfile] - [1] FlagEncoders: 1, bits used [UNKNOWN]/64.
2021-10-01 07:47:49,314 INFO [routing.RoutingProfile] - [1] Capacity: [UNKNOWN]. (edges - 1163561, nodes - 902218)
2021-10-01 07:47:49,317 INFO [routing.RoutingProfile] - [1] Total time: 2561.002s.
2021-10-01 07:47:49,320 INFO [routing.RoutingProfile] - [1] Finished at: 2021-10-01 07:47:49.
2021-10-01 07:47:49,322 INFO [routing.RoutingProfile] -                               
2021-10-01 07:47:49,330 INFO [routing.RoutingProfileManager] - Total time: 2561.307s.
2021-10-01 07:47:49,332 INFO [routing.RoutingProfileManager] - ========================================================================
2021-10-01 07:47:49,339 INFO [routing.RoutingProfileManager] - ====> Recycling garbage...
2021-10-01 07:47:49,341 INFO [routing.RoutingProfileManager] - Before:  Total - 1.88 GB, Free - 337.71 MB, Max: 2 GB, Used - 1.55 GB
2021-10-01 07:47:49,443 INFO [routing.RoutingProfileManager] - After:  Total - 1.88 GB, Free - 1.26 GB, Max: 2 GB, Used - 632.27 MB
2021-10-01 07:47:49,445 INFO [routing.RoutingProfileManager] - ========================================================================
2021-10-01 07:47:49,447 INFO [routing.RoutingProfileManager] - ====> Memory usage by profiles:
2021-10-01 07:47:49,500 INFO [routing.RoutingProfileManager] - [1] 252.03 MB (39.9%)
2021-10-01 07:47:49,502 INFO [routing.RoutingProfileManager] - Total: 252.03 MB (39.9%)
2021-10-01 07:47:49,504 INFO [routing.RoutingProfileManager] - ========================================================================
2021-10-01 08:02:00,791 INFO [util.SystemMessage] - SystemMessage loaded 0 messages.

Found an forum post but without any answer
https://ask.openrouteservice.org/t/docker-image-is-there-a-log-of-the-graph-building-process/5410

Possible Implementation

Maybe an ENV var? Or an dedicated JVM option?

Forum Topic Link

No response

[sfendrich]

Configuring the logging in the config file should be sufficient. If you are using the new yml-based configuration you need to make sure that there is no old json-config lying around, which may override your yml-config.

[JPBM135]

I tried only the configuration and it ignores it, I also made sure there was no json nearby

[MichaelsJP]

@JPBM135 The logging in containers is known to be tricky. Please review this problem once v8 is out. We're actively working on it and it will be soon. We've currently come competing log libraries that should be sorted out in v8.

[JPBM135]

Amazing to know, I will wait anxiously!!!