Repository navigation
Confusing middle pgsql processing. #2049
Description
What version of osm2pgsql are you using?
osm2pgsql version 1.8.0
What operating system and PostgreSQL/PostGIS version are you using?
Linux Debian Stable, PG Database version: 15.3 (Debian 15.3-0+deb12u1), PostGIS version: 3.3
Tell us something about your system
Small server, 8GiB RAM, 1TB consumer SATA SSD.
What did you do exactly?
osm2pgsql --verbose --database gis --cache 0 --number-processes 4 --slim --flat-nodes $(pwd)/nodes.cache --hstore --multi-geometry --style $osm_carto/openstreetmap-carto.style --tag-transform-script $osm_carto/openstreetmap-carto.lua europe-latest.osm.pbf
What did you expect to happen?
The logs about the middle processing are a little bit confusing:
2023-08-19 20:49:52 [1] Clustering table 'planet_osm_polygon' by geometry...
2023-08-19 20:49:52 [2] Clustering table 'planet_osm_line' by geometry...
2023-08-19 20:49:52 [3] Clustering table 'planet_osm_roads' by geometry...
2023-08-19 20:49:52 [4] Clustering table 'planet_osm_point' by geometry...
2023-08-19 20:49:52 [1] Using native order for clustering table 'planet_osm_polygon'
2023-08-19 20:49:52 [2] Using native order for clustering table 'planet_osm_line'
2023-08-19 20:49:52 [3] Using native order for clustering table 'planet_osm_roads'
2023-08-19 20:49:52 [4] Using native order for clustering table 'planet_osm_point'
2023-08-19 22:35:50 [3] Creating geometry index on table 'planet_osm_roads'...
2023-08-19 22:50:47 [3] Creating osm_id index on table 'planet_osm_roads'...
2023-08-19 22:55:52 [3] Analyzing table 'planet_osm_roads'...
2023-08-19 22:57:47 [3] Done task in 7674389ms.
2023-08-19 22:57:47 [3] Starting task...
2023-08-19 22:57:47 [3] Done task in 1ms.
2023-08-19 22:57:47 [3] Starting task...
2023-08-19 22:57:47 [0] Done postprocessing on table 'planet_osm_nodes' in 0s
2023-08-19 22:57:47 [3] Building index on table 'planet_osm_ways'
2023-08-19 23:32:06 [4] Creating geometry index on table 'planet_osm_point'...
2023-08-20 00:13:30 [4] Creating osm_id index on table 'planet_osm_point'...
2023-08-20 00:20:35 [4] Analyzing table 'planet_osm_point'...
2023-08-20 00:20:40 [4] Done task in 12647156ms.
2023-08-20 00:20:40 [4] Starting task...
2023-08-20 00:20:40 [4] Building index on table 'planet_osm_rels'
2023-08-20 02:03:11 [4] Done task in 6151838ms.
2023-08-20 03:17:24 [2] Creating geometry index on table 'planet_osm_line'...
2023-08-20 03:54:40 [2] Creating osm_id index on table 'planet_osm_line'...
2023-08-20 04:02:57 [2] Analyzing table 'planet_osm_line'...
2023-08-20 04:03:01 [2] Done task in 25988218ms.
2023-08-20 05:26:21 [1] Creating geometry index on table 'planet_osm_polygon'...
2023-08-20 06:17:31 [1] Creating osm_id index on table 'planet_osm_polygon'...
2023-08-20 06:30:46 [1] Analyzing table 'planet_osm_polygon'...
2023-08-20 06:30:47 [1] Done task in 34854542ms.
2023-08-20 10:48:18 [3] Done task in 42630605ms.
2023-08-20 10:48:18 [0] Done postprocessing on table 'planet_osm_ways' in 42630s (11h 50m 30s)
2023-08-20 10:48:18 [0] Done postprocessing on table 'planet_osm_rels' in 6151s (1h 42m 31s)
I separated it in sections by worker. The messages about Starting task and Done task don't mention which task it is. Also, do I understand correctly that not all workers started working at the same time? If I'm right, why is that? If I Isolate worker 3's logs:
2023-08-19 20:49:52 [3] Clustering table 'planet_osm_roads' by geometry...
2023-08-19 20:49:52 [3] Using native order for clustering table 'planet_osm_roads'
2023-08-19 22:35:50 [3] Creating geometry index on table 'planet_osm_roads'...
2023-08-19 22:50:47 [3] Creating osm_id index on table 'planet_osm_roads'...
2023-08-19 22:55:52 [3] Analyzing table 'planet_osm_roads'...
2023-08-19 22:57:47 [3] Done task in 7674389ms.
2023-08-19 22:57:47 [3] Starting task...
2023-08-19 22:57:47 [3] Done task in 1ms.
2023-08-19 22:57:47 [3] Starting task...
2023-08-19 22:57:47 [3] Building index on table 'planet_osm_ways'
2023-08-20 10:48:18 [3] Done task in 42630605ms.
2023-08-20 10:48:18 [0] Done postprocessing on table 'planet_osm_ways' in 42630s (11h 50m 30s)
At 20:49 starts processing roads. ~2h later it's creating 2 indexes and analyzing it. Launches 2 tasks, but finishes one first (22:57), a long one? Which one? And then another, but one seems to still be running.
And suddenly it's creating indexes on ways. This seems to finish the next day and it's properly logged.
I also see the messages about 'Done postprocessing' for nodes (22:57), ways and rels (next day, 10:48), but for the other 4 tables the message is `All postprocessing'.
Could tasks be more verbose about what exactly they're doing? I didn't try --log-level=debug because this is a 49h+ process and I really don't want to start it all over :)
Activity
StyXman commentedon Aug 22, 2023
I tried to make sense of this part. We have 4 workers 1-4 plus one main thread 0. On the 19th, ~20:50, all four workers
start working on
polygon,line,roadsandpointrespectively. 2h07m54s later worker 3 finishes clusteringroads, which is reported at the end of the run. But immediately starts creating indexes for it, which takes ~15m and~5m each. It starts analyzing
roads, which I guess it's the task that finishes at 22:57 (~2m runtime).Then 2 anonymous tasks, one finishes in 1ms, and the second lingers...? And immediately starts indexing
ways.Meanwhile,
nodes, which wasn't reported as being processed by any worker, also finishes. Maybe it's the main loopwhich does it? And if so, why did it finish only now, after only 0s? All this happens on the same second.
Still on the 19th, at ~23:32, worker 4 starts creating indexes for
point. This is ~3h30m after it startedclustering it, which is also what is reported at the end. Again, 2 indexes and one analysis for this table, then an
anonymous task... which I guess finishes immediately? Because on the same second it creates an index for it, which looks
like a pattern (W3 did the same, remember?). It finishes in ~1h40m, so I guess W3's "Done task" at the end is the index
it was creating since the 19th?
Given all that, I added extra annotations that I think are the right ones to make sense of all that. I hope I can use
some of my plenty spare time to fix it:
StyXman commentedon Aug 22, 2023
The mix of ms, s and hms is a little bit haphazard, and the reported times don't seem to reflect all post processing.
joto commentedon Aug 22, 2023
This basically goes in the same direction as #207.
What and how things are logged as changed over time and there never was a grand plan how to do this. I totally agree that the logging is hard to understand for somebody new to the project. You really have to know a lot about the internals of osm2pgsql processing to interpret the output. Osm2pgsql internal processing is complex and the question is, how much the user should actually see of how the sausage is made. Maybe we should just move all that logging to the debug mode and only tell the user when we are done? Does the user actually need to know? What information is actually actionable to the user? On the other hand we could add a lot more output, trying to make things clearer, but that would be a lot of information.
So the question is really: What is that output for? And for whom? Currently it is for experts who want to see what's going on, either in their own setups, or, more importantly, when users report problems. @StyXman What do you expect of that output?
Coincidentally I recently added https://osm2pgsql.org/contribute/how-osm2pgsql-processing-works.html to the website to help explain more about what goes on inside osm2pgsql. Could help with figuring out things, although it is just a small part of what's going on.
StyXman commentedon Aug 22, 2023
I'm using the logs to generate annotations on a grafana server like this:
so I don't want to know how the sausage is made, but at least I want the fabrication and expiring date of each package I buy :)
joto commentedon Aug 22, 2023
But what are you creating those graphs for? What is it that you are trying to achieve in the end?
StyXman commentedon Aug 22, 2023
Right now it's investigate how disk usage changes during the import. Later it will allow me to know how updates change too. I hope to finish soon with a write up about it.
StyXman commentedon Aug 23, 2023
This level of logging could be done on a
--log-level verbosemode. If you want, we can discuss it over IRC, I'm on the #osm channel, OFTC network.