Osrm-backend: osrm-extract I/O error on larger osm PBFs

[rvv2017]

Hello,

I get the following error: "[error] I/O error occurred: planet-180326.osrm : /extractor/barriers (possible cause: "Resource temporarily unavailable") (at include/storage/tar.hpp:59)"
planet-180326.osrm is produced, but not the .ebg, .hsgr etc output.

40GB osm.pbf file being extracted on a server with 256GB RAM + 200GB swap space (not really needed).
Car profile.
Tried both version 5.17 and 5.16 of osrm-backend, compiled (successfully) with multiple versions of cmake.
Tried several versions of planet.osm.pbf (2018/01/01 and 2018/03/22 from https://ftpmirror.your.org/pub/openstreetmap/pbf/

The same setup(s) extract/contract/route correctly smaller maps (France, Germany - 3-4GB range), but not Europe (20GB range).
The last lines of output prior to the error are pasted below.

Any suggestions?
Thanks!

[info] Parsing finished after 1164.68 seconds
[info] Raw input contains 113947963 nodes, 479968666 ways, and 519801 relations, 806239 restrictions
[info] Sorting used nodes ... ok, after 6.02309s
[info] Erasing duplicate nodes ... ok, after 2.08025s
[info] Sorting all nodes ... ok, after 1.12528s
[info] Building node id map ... ok, after 9.08687s
[info] Confirming/Writing used nodes ... ok, after 47.958s
[info] Writing barrier nodes ... ok, after 0s
[info] Writing traffic light nodes ... ok, after 0s
[info] Processed 738328516 nodes
[info] Sorting edges by start ... ok, after 27.7846s
[info] Setting start coords ... ok, after 72.6588s
[info] Sorting edges by target ... ok, after 27.6028s
[info] Computing edge weights ... ok, after 152.04s
[info] Sorting edges by renumbered start ... ok, after 27.4838s
[info] Writing used edges ... ok, after 11.2787s -- Processed 779241334 edges
[info] Writing way meta-data ... ok, after 0.435582s -- Metadata contains << 85809205 entries.
[info] Sorting used ways ... ok, after 0.055978s
[info] Collecting start/end information on 2 maneuver overrides...ok, after 1.68329s
[info] Collecting start/end information on 2 maneuver overrides...ok, after 1.6e-05s
[info] Collecting start/end information on 806239 restrictions...ok, after 7.60728s
[info] Collecting start/end information on 806239 restrictions...ok, after 1.04194s
[info] writing street name index ... ok, after 0.63277s
[info] extraction finished after 1580.12s
[info] Generating edge-expanded graph representation
[info] RAM: peak bytes used: 160217108480
[error] I/O error occurred: planet-180326.osrm : /extractor/barriers (possible cause: "Resource temporarily unavailable") (at include/storage/tar.hpp:59)

[danpat]

@rvv2017 "Resource Temporarily Unavailable" is an operating system error message. Your system is running out of something, although the error message doesn't say what (and AFAIK, there's no easy way for OSRM to figure out what either :-/).

The message immediately prior to the error "[info] Generating edge-expanded graph representation" indicates one of osrm-extracts more memory-intensive phases - lots of RAM is used here.

I don't think this is a problem with OSRM per-se, but rather some limits within your system that you're running into. I would do the following:

1. Check ulimit and see if your system has any low limits configured by default.
2. Check your system logs to see if the kernel has logged any errors around the time that OSRM barfs.
3. Do a Google search for "Resource temporarily unavailable" and see what kinds of issues people are discussing, maybe one of those applies to your system.

While OSRM master (5.17 prerelease) uses a new on-disk storage format, the fact that you're getting the same kind of error with OSRM 5.16 (which uses the old disk data format) indicates that it's probably not related to the disk layout refactoring.

The fact that you only see this on large files but not small ones also hints at some kind of resource shortfall on your system.

If all else fails, you can try re-compiling OSRM with the cmake -DENABLE_STXXL=ON .. option. This will cause OSRM to use less real RAM and instead use optimized disk swapping. It'll mean things run a little bit slower, but not too much, and you will need a much smaller amount of peak RAM.

If RAM is the problem, I don't know why you're not getting a regular out-of-memory error 🤷‍♂️

[rvv2017]

Thanks for the prompt reply!

Small update on this one: the server has been upgraded to 960GB RAM and 64 cores (AWS).

Monitoring vmstat shows the available RAM is never under 500GB.
ulimit indicates "unlimited"
Nothing unusual in the syslog file (Ubuntu). zgrep -i mem /var/log/syslog* shows only reboot-related messages.

Latest attempts fail with a different error. This one is from the most recent europe-latest.osm.pbf extract (20GB).

[error] Unexpected end of file: /extractor/edges: Datatype size does not match file size. (at include/storage/tar.hpp:149)

I ran it within the gdb tool with:
gdb -ex "run" -ex "bt" -ex "info locals" -ex "info arg" -ex "quit" --args osrm-extract - p profiles/car.lua europe-latest.osm.pbf

The tail of the console output is below.
What would be your guess?
Thanks!

....
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[Thread 0x7fffe2fc2700 (LWP 4089) exited]
[Thread 0x7fffe27c1700 (LWP 4090) exited]
[info] Parsing finished after 450.179 seconds
[info] Raw input contains 2064758798 nodes, 251237988 ways, and 382252 relations, 458324 restrictions
[info] Sorting used nodes ... ok, after 2.30648s
[info] Erasing duplicate nodes ... ok, after 0.780366s
[info] Sorting all nodes ... ok, after 0.60118s
[info] Building node id map ... ok, after 7.06481s
[info] Confirming/Writing used nodes ... ok, after 20.0192s
[info] Writing barrier nodes ... ok, after 0s
[info] Writing traffic light nodes ... ok, after 0s
[info] Processed 236711952 nodes
[info] Sorting edges by start ... ok, after 10.1048s
[info] Setting start coords ... ok, after 28.9526s
[info] Sorting edges by target ... ok, after 10.4853s
[info] Computing edge weights ... ok, after 61.3489s
[info] Sorting edges by renumbered start ... ok, after 11.1403s
[info] Writing used edges ... ok, after 6.27168s -- Processed 247886147 edges
[info] Writing way meta-data ... ok, after 0.193306s -- Metadata contains << 31462812 entries.
[info] Sorting used ways ... ok, after 0.02427s
[info] Collecting start/end information on 0 maneuver overrides...ok, after 0.395453s
[info] Collecting start/end information on 0 maneuver overrides...ok, after 1e-06s
[info] Collecting start/end information on 458324 restrictions...ok, after 3.8035s
[info] Collecting start/end information on 458324 restrictions...ok, after 0.717604s
[info] writing street name index ... ok, after 0.184597s
[info] extraction finished after 620.891s
[Thread 0x7fffe4fc6700 (LWP 3932) exited]
[Thread 0x7fffe57c7700 (LWP 3931) exited]
[Thread 0x7fffe3fc4700 (LWP 3934) exited]
[Thread 0x7fffe8fce700 (LWP 3924) exited]
[Thread 0x7fffe9fd0700 (LWP 3922) exited]
[Thread 0x7fffed7d7700 (LWP 3915) exited]
[Thread 0x7fffee7d9700 (LWP 3913) exited]
[Thread 0x7fffeffdc700 (LWP 3910) exited]
[Thread 0x7fffe87cd700 (LWP 3925) exited]
[Thread 0x7fffec7d5700 (LWP 3917) exited]
[Thread 0x7ffff0fde700 (LWP 3908) exited]
[Thread 0x7fffe7fcc700 (LWP 3926) exited]
[Thread 0x7ffff2fe2700 (LWP 3904) exited]
[Thread 0x7ffff1fe0700 (LWP 3906) exited]
[Thread 0x7fffe5fc8700 (LWP 3930) exited]
[Thread 0x7fffe67c9700 (LWP 3929) exited]
[Thread 0x7ffff07dd700 (LWP 3909) exited]
[Thread 0x7fffe47c5700 (LWP 3933) exited]
[Thread 0x7fffedfd8700 (LWP 3914) exited]
[Thread 0x7fffe77cb700 (LWP 3927) exited]
[Thread 0x7fffeafd2700 (LWP 3920) exited]
[Thread 0x7fffecfd6700 (LWP 3916) exited]
[Thread 0x7ffff17df700 (LWP 3907) exited]
[Thread 0x7fffe97cf700 (LWP 3923) exited]
[Thread 0x7fffe6fca700 (LWP 3928) exited]
[Thread 0x7fffea7d1700 (LWP 3921) exited]
[Thread 0x7ffff27e1700 (LWP 3905) exited]
[Thread 0x7fffeb7d3700 (LWP 3919) exited]
[Thread 0x7fffebfd4700 (LWP 3918) exited]
[Thread 0x7fffe37c3700 (LWP 3935) exited]
[Thread 0x7fffeefda700 (LWP 3912) exited]
[Thread 0x7fffef7db700 (LWP 3911) exited]
[info] Generating edge-expanded graph representation
[Thread 0x7ffedc7f1700 (LWP 4077) exited]
[Thread 0x7fff35bf6700 (LWP 4043) exited]
[Thread 0x7ffedeffb700 (LWP 4061) exited]
[Thread 0x7ffed6bfa700 (LWP 4084) exited]
[Thread 0x7ffede3f8700 (LWP 4075) exited]
[Thread 0x7fff52bfa700 (LWP 4110) exited]
[Thread 0x7fff0c7f1700 (LWP 4067) exited]
[Thread 0x7fffe1090700 (LWP 4093) exited]
[Thread 0x7fff0f7fd700 (LWP 4053) exited]
[Thread 0x7fff50bf9700 (LWP 4116) exited]
[Thread 0x7ffed7fff700 (LWP 4079) exited]
[Thread 0x7fff367f9700 (LWP 4041) exited]
[Thread 0x7ffed5ff7700 (LWP 4130) exited]
[Thread 0x7fff0d7f5700 (LWP 4059) exited]
[Thread 0x7fff6affc700 (LWP 4086) exited]
[Thread 0x7fff4eff4700 (LWP 4119) exited]
[Thread 0x7fff4dff0700 (LWP 4125) exited]
[Thread 0x7ffedd3f4700 (LWP 4076) exited]
[Thread 0x7fff363f8700 (LWP 4040) exited]
[Thread 0x7ffedcff3700 (LWP 4072) exited]
[Thread 0x7fff0e3f8700 (LWP 4056) exited]
[Thread 0x7ffeddff7700 (LWP 4073) exited]
[Thread 0x7fff0effb700 (LWP 4050) exited]
[Thread 0x7ffedd7f5700 (LWP 4069) exited]
[Thread 0x7fff52ffb700 (LWP 4109) exited]
[Thread 0x7fff68ff7700 (LWP 4104) exited]
[Thread 0x7fffe048d700 (LWP 4096) exited]
[Thread 0x7fff537fd700 (LWP 4105) exited]
[Thread 0x7ffed67f9700 (LWP 4081) exited]
[Thread 0x7fff51ff7700 (LWP 4113) exited]
[Thread 0x7fff69ff8700 (LWP 4101) exited]
[Thread 0x7ffedf3fc700 (LWP 4060) exited]
[Thread 0x7fff35ff7700 (LWP 4039) exited]
[Thread 0x7fffe0c8f700 (LWP 4094) exited]
[Thread 0x7fff53bfe700 (LWP 4103) exited]
[Thread 0x7fff0ebfa700 (LWP 4049) exited]
[Thread 0x7fff0f3fc700 (LWP 4048) exited]
[Thread 0x7ffede7f9700 (LWP 4071) exited]
[Thread 0x7ffed7bfe700 (LWP 4082) exited]
[Thread 0x7fff0dbf6700 (LWP 4057) exited]
[Thread 0x7fff687f6700 (LWP 4030) exited]
[Thread 0x7fff37bfe700 (LWP 4033) exited]
[Thread 0x7fff527f9700 (LWP 4111) exited]
[Thread 0x7fff0dff7700 (LWP 4055) exited]
[Thread 0x7fff34ff3700 (LWP 4054) exited]
[Thread 0x7ffedf7fd700 (LWP 4066) exited]
[Thread 0x7fff373fc700 (LWP 4037) exited]
[Thread 0x7fff6a7fa700 (LWP 4102) exited]
[Thread 0x7fff4e3f1700 (LWP 4121) exited]
[Thread 0x7fff53fff700 (LWP 4029) exited]
[Thread 0x7fffe1892700 (LWP 4026) exited]
[Thread 0x7fff357f5700 (LWP 4044) exited]
[Thread 0x7fff6bbfe700 (LWP 4027) exited]
[Thread 0x7fff4fff8700 (LWP 4031) exited]
[Thread 0x7fff347f1700 (LWP 4047) exited]
[Thread 0x7fff353f4700 (LWP 4045) exited]
[Thread 0x7fff50ffa700 (LWP 4032) exited]
[Thread 0x7fffe1fc0700 (LWP 4025) exited]
[Thread 0x7fff0e7f9700 (LWP 4058) exited]
[Thread 0x7fff0fbfe700 (LWP 4052) exited]
[Thread 0x7ffeddbf6700 (LWP 4074) exited]
[Thread 0x7fff0cbf2700 (LWP 4062) exited]
[Thread 0x7fff36bfa700 (LWP 4042) exited]
[Thread 0x7fff377fd700 (LWP 4038) exited]
[Thread 0x7fff523f8700 (LWP 4112) exited]
[Thread 0x7ffed73fc700 (LWP 4087) exited]
[Thread 0x7ffedcbf2700 (LWP 4078) exited]
[Thread 0x7fff6a3f9700 (LWP 4100) exited]
[Thread 0x7fff37fff700 (LWP 4034) exited]
[Thread 0x7ffed77fd700 (LWP 4083) exited]
[Thread 0x7ffedffff700 (LWP 4064) exited]
[Thread 0x7fff6abfb700 (LWP 4099) exited]
[Thread 0x7fff4c7f4700 (LWP 4035) exited]
[Thread 0x7fff697f8700 (LWP 4028) exited]
[Thread 0x7ffedebfa700 (LWP 4070) exited]
[Thread 0x7fff4f3f5700 (LWP 4124) exited]
[Thread 0x7fffe1491700 (LWP 4092) exited]
[Thread 0x7ffedfbfe700 (LWP 4063) exited]
[Thread 0x7fff533fc700 (LWP 4108) exited]
[Thread 0x7fff0d3f4700 (LWP 4068) exited]
[Thread 0x7fff4d3ed700 (LWP 4128) exited]
[Thread 0x7fff4dbef700 (LWP 4126) exited]
[Thread 0x7fff517f5700 (LWP 4114) exited]
[Thread 0x7fff0cff3700 (LWP 4065) exited]
[Thread 0x7ffed63f8700 (LWP 4080) exited]
[Thread 0x7fff6bfff700 (LWP 4097) exited]
[Thread 0x7ffed6ffb700 (LWP 4085) exited]
[Thread 0x7fff36ffb700 (LWP 4036) exited]
[Thread 0x7fff6b7fd700 (LWP 4098) exited]
[Thread 0x7fff4ebf3700 (LWP 4123) exited]
[Thread 0x7fffe088e700 (LWP 4095) exited]
[Thread 0x7fff4d7ee700 (LWP 4127) exited]
[Thread 0x7fff4fbf7700 (LWP 4117) exited]
[Thread 0x7fff51bf6700 (LWP 4115) exited]
[Thread 0x7fff4cfec700 (LWP 4129) exited]
[Thread 0x7fff4e7f2700 (LWP 4122) exited]
[Thread 0x7fff507f8700 (LWP 4118) exited]
[Thread 0x7fff4f7f6700 (LWP 4120) exited]
[Thread 0x7fff0ffff700 (LWP 4051) exited]
[Thread 0x7fff34bf2700 (LWP 4046) exited]
[info] RAM: peak bytes used: 60540940288
[error] Unexpected end of file: /extractor/edges: Datatype size does not match file size. (at include/storage/tar.hpp
[Inferior 1 (process 3900) exited with code 010]
No stack.
No frame selected.
No frame selected.

[danpat]

@rvv2017 ok, glad we got around the "Resource Temporarily Unavailable" error - I suspect the memory increase helped there.

[error] Unexpected end of file: /extractor/edges: Datatype size does not match file size. (at include/storage/tar.hpp

looks like it could be a bug in the new on-disk data format. That code is still on master, which is not a stable release yet, so it may have a problem.

I would suggest re-trying with the official OSRM 5.16 release - this uses the old on-disk data format that's been around for a while.

Make sure to remove any stale .osrm* files before re-running.

[rvv2017]

Thanks for the help Daniel, v5.16.4 worked great. Europe map processed on a much smaller system (<200GB RAM); we'll see about a "full planet"...

[bpstewar]

Can I piggyback off of this? I am running into a similar problem running osrm-extract on all of Africa and I get the error below. You suggest running the ulimit command to see what's up, but I don't really know how to interpret this, any help? Ulimit command is included below

PS C:\Code> docker run -i -t -v D:/OSRM/Africa:/data osrm/osrm-backend
>>
/opt # osrm-extract -p /opt/car.lua /data/africa-latest.o5m
[info] Parsed 0 location-dependent features with 0 GeoJSON polygons
[info] Using script /opt/car.lua
[info] Input file: africa-latest.o5m
[info] Profile: car.lua
[info] Threads: 11
[info] Parsing in progress..
[info] input file generated by unknown tool
[info] timestamp: n/a
[info] Using profile api version 4
[info] Found 3 turn restriction tags:
[info]   motorcar
[info]   motor_vehicle
[info]   vehicle
[info] Parse relations ...
[info] Parse ways and nodes ...
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Using profile api version 4
[info] Parsing finished after 1070.53 seconds
[info] Raw input contains 372076217 nodes, 44712578 ways, and 7912 relations, 12776 restrictions
[info] Sorting used nodes        ... ok, after 0.688427s
[info] Erasing duplicate nodes   ... ok, after 0.145841s
[info] Sorting all nodes         ... ok, after 0.152998s
[info] Building node id map      ... ok, after 0.604386s
[info] Confirming/Writing used nodes     ... ok, after 3.81685s
[info] Writing barrier nodes     ... ok, after 0s
[info] Writing traffic light nodes     ... ok, after 0s
[info] Processed 64941986 nodes
[info] Sorting edges by start    ... ok, after 2.69124s
[info] Setting start coords      ... ok, after 4.35799s
[info] Sorting edges by target   ... ok, after 2.61856s
[info] Computing edge weights    ... ok, after 9.51651s
[info] Sorting edges by renumbered start ... ok, after 2.76257s
[info] Writing used edges       ... ok, after 1.81827s -- Processed 68292646 edges
[info] Writing way meta-data     ... ok, after 0.021776s -- Metadata contains << 5606269 entries.
[info] Sorting used ways         ... ok, after 0.007395s
[info] Collecting start/end information on 0 maneuver overrides...ok, after 0.048281s
[info] Collecting start/end information on 0 maneuver overrides...ok, after 0s
[info] Collecting start/end information on 12776 restrictions...ok, after 0.377948s
[info] Collecting start/end information on 12776 restrictions...ok, after 0.01953s
[info] writing street name index ... ok, after 0.047406s
[info] extraction finished after 1123.99s
[info] Generating edge-expanded graph representation
[info] RAM: peak bytes used: 15653412864
[error] Problem reading from file: /data/africa-latest.o5m.osrm : /extractor/edges (possible cause: "I/O error") (at include/storage/tar.hpp:44)

/opt # ulimit -a
-f: file size (blocks)             unlimited
-t: cpu time (seconds)             unlimited
-d: data seg size (kb)             unlimited
-s: stack size (kb)                8192
-c: core file size (blocks)        0
-m: resident set size (kb)         unlimited
-l: locked memory (kb)             82000
-p: processes                      unlimited
-n: file descriptors               1048576
-v: address space (kb)             unlimited
-w: locks                          unlimited
-e: scheduling priority            0
-r: real-time priority             0

[TheMarex]

I think I found a possible location where a write can silently fail, I'll look into this.

[JK87iab]

Hi I experience a similar error. In the past I had no problem installing the map on a 70GB Ram machine.

`
jonas_krueger_h71@osrm:~$ sudo docker run -t -v $(pwd):/data osrm/osrm-backend osrm-extract -p
/opt/car.lua /data/north-america-latest.osm.pbf

[info] Parsed 0 location-dependent features with 0 GeoJSON polygons

[info] Using script /opt/car.lua

[info] Input file: north-america-latest.osm.pbf

[info] Profile: car.lua
[info] Threads: 2
[info] Parsing in progress..
[info] input file generated by osmium/1.5.1
[info] timestamp: 2018-04-01T20:44:02Z
[info] Using profile api version 4
[info] Found 3 turn restriction tags:
[info] motorcar
[info] motor_vehicle
[info] vehicle
[info] Parse relations ...
[info] Parse ways and nodes ...
[info] Using profile api version 4
[info] Parsing finished after 3995 seconds
[info] Raw input contains 969998936 nodes, 73421994 ways, and 64271 relations, 166536 restrictions
[info] Sorting used nodes ... ok, after 13.5597s
[info] Erasing duplicate nodes ... ok, after 0.787247s
[info] Sorting all nodes ... ok, after 8.99404s
[info] Building node id map ... ok, after 2.6663s
[info] Confirming/Writing used nodes ... ok, after 31.1257s
[info] Writing barrier nodes ... ok, after 0s
[info] Writing traffic light nodes ... ok, after 0s
[info] Processed 203315931 nodes
[info] Sorting edges by start ... ok, after 30.7551s
[info] Setting start coords ... ok, after 18.8122s
[info] Sorting edges by target ... ok, after 29.6639s
[info] Computing edge weights ... ok, after 40.6305s
[info] Sorting edges by renumbered start ... ok, after 30.5436s
[info] Writing used edges ... ok, after 5.79068s -- Processed 214366904 edges
[info] Writing way meta-data ... ok, after 0.147065s -- Metadata contains << 21927083 entries.
[info] Sorting used ways ... ok, after 0.108876s
[info] Collecting start/end information on 2 maneuver overrides...ok, after 0.408543s
[info] Collecting start/end information on 2 maneuver overrides...ok, after 4.6e-05s
[info] Collecting start/end information on 166536 restrictions...ok, after 3.34355s
[info] Collecting start/end information on 166536 restrictions...ok, after 0.308135s
[info] writing street name index ... ok, after 0.157644s
[info] extraction finished after 4231.66s
[info] Generating edge-expanded graph representation
[info] RAM: peak bytes used: 35373346816
[error] Unexpected end of file: /extractor/edges: Datatype size does not match file size. (at include/storage/tar.hpp:149)`