Confusing middle pgsql processing.

[StyXman]

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 :)

[StyXman]

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, roads and point respectively. 2h07m54s later worker 3 finishes clustering
roads, 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 loop
which 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 started
clustering 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:

    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 [Analyzing table 'planet_osm_roads'] in 7674389ms.
    2023-08-19 22:57:47  [3] Starting task [which one?]...
    2023-08-19 22:57:47  [3] Done task in 1ms.
    2023-08-19 22:57:47  [3] Starting task [which one?]...

    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 [Analyzing table 'planet_osm_point'] 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 [Building index on table 'planet_osm_rels'] 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 [Analyzing table 'planet_osm_line'] 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 [Analyzing table 'planet_osm_polygon'] in 34854542ms.

    2023-08-20 10:48:18  [3] Done task [Building index on table 'planet_osm_ways'] 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)

    2023-08-20 10:48:18  [0] All postprocessing on table 'planet_osm_point' done in 12647s (3h 30m 47s).
    2023-08-20 10:48:18  [0] All postprocessing on table 'planet_osm_line' done in 25988s (7h 13m 8s).
    2023-08-20 10:48:18  [0] All postprocessing on table 'planet_osm_polygon' done in 34854s (9h 40m 54s).
    2023-08-20 10:48:18  [0] All postprocessing on table 'planet_osm_roads' done in 7674s (2h 7m 54s).

    2023-08-20 10:48:18  [0] Overall memory usage: peak=85815MByte current=727MByte
    2023-08-20 10:48:18  [0] osm2pgsql took 154917s (43h 1m 57s) overall.

[StyXman]

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]

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]

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]

But what are you creating those graphs for? What is it that you are trying to achieve in the end?

[StyXman]

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]

This level of logging could be done on a --log-level verbose mode. If you want, we can discuss it over IRC, I'm on the #osm channel, OFTC network.

[rustprooflabs]

👍 I'm in the camp of wanting more detail but I also see the value in a minimized, more straightforward output. Especially for new users. I'd be happy to use a --log-level option to get the extra detail.

[StyXman]

@joto I'm starting to look into this. Can you confirm my findings are 100% correct? Can you also provide any pointers that would save me some time finding myself around the code? OK, I found everything in src/middle-pgsql.cpp.