OSM2PostGIS / Bugs / #12 performance question-medium dataset

Sakari A. Maaranen - 2010-03-31

I'm pretty sure the problem is with PostgreSQL performance tuning. I am running OSM2PostGIS with the full planet.osm file (of date 2010-01-13), so I'm running it with the largest possible data set of over 115 GiB, and I have no performance problems.

Here are a couple of log lines from my latest test that is currently running:

2010-03-31 07:40:39.883 net.sourceforge.osm2postgis.core.Monitor run
INFO: Time elapsed 2 d 16:44:04; Committed up to line 386761583; Throughput 1193.2 entities/s.
2010-03-31 07:40:39.883 net.sourceforge.osm2postgis.core.Monitor run
INFO: Cumulative: public.osm_changesets:created=3607228 public.osm_nodes:created=263817329

In other words, on my servers it has processed 3.6 million changesets and 263.8 million nodes in 2 days 16 h 44 minutes.

I know it may be frustrating to interrupt the process after the days you have been waiting, but don't worry because you can resume from where you left after tuning the database. Just check from the logs the last input line committed, and use the -s command line option to specify the start line on your next run.

I'm attaching my PostgreSQL configuration file that is tuned for my dedicated database server with 4 GiB RAM. You should read the PostgreSQL tuning instructions and find appropriate settings for your server. My settings may be too high, if you have less RAM for your database.

If tuning doesn't help, then we should inspect which tables and indexes you have in the database. They should be OK, if you have created the schema with a relatively recent version of OSM2PostGIS.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-03-31

PostgreSQL 8.1.18 configuration for a server with 4 GiB RAM

postgresql.conf

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-03-31

Hmm, there is on difference with our test runs. You are already at the feature detection phase that is quite different from the basic input phase. So, if there is a bug, I would notice it in my tests only after all the nodes, ways and relations are imported first. It will take over a week before my current test run is there, so let's see how it goes then.

Meanwhile, you could use the admin scripts in the sql subdirectory to manually get a list of your tables and indexes in the OSM2PostGIS database. If you can post or attach those lists, we can verify that all the required indexes are in place. The performance could drop dramatically with large datasets, if some indexes were missing and the database was forced to scan full tables instead of indexes.

Anyway, it's possible it's just a question of tuning, but bugs are still possible and I wouldn't know before my test run is at the same phase as yours is now.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-03-31

colorado.osm test run

osm2postgis.rar

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-03-31

I stopped the maryland.osm test run before heading home last night and tuned some of the parameters (I'll try yours later, thanks). I restarted the server and launched a test run using colorado.osm from cloudmade. It crashed after about 10 hrs. Log file is attached.

I'm repeating my original maryland.osm test to see if anything different develops. But in general it seems the parsing phase where the nodes, ways, etc are created proceeds pretty routinely. It's after that that things tend to grind. It will be interesting to see what some larger buffers will do. Thanks!

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-01

I've tried a couple of different angles with respect to performance tuning. Unfortunately the diffs between our postgresql versions precludes a 100% exact same test. But in three separate tests, enlarging buffer sizes etc didn't seem to have much effect. However, turning off fsync did- the installation of the osm_nodes table almost doubled in throughput (albeit risky from the standpoint of a power hit or other problem). The osm_ways table throughput didn't change much.

It still seems like everything does quite well until the "parsing ended" statement. At that point it starts to grind sometimes with only one or two row changes in a 10 minute period.

Also, I tried the admin sql commands to capture the indexes, but they didn't run. Perhaps a delta in our pg versions may be the cause. Using PGAdmin III, I can see where indexes have been created for some of the tables.

Here is a screen capture at the point parsing ends:

16:20 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.osm_relation_tags (id,k,v) VALUES (
,?,?);
16:20 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.osm_relation_members (id,type,ref,r
le,sequence) VALUES (?,?,?,?,?);
16:20 2postgis.core.OSMHandler endElement FINER: End of OSM data: </osm>
16:20 2postgis.core.OSMHandler endDocument FINER: End of XML document.
Done file: E:\Osm\maryland.osm
16:20 m2postgis.core.OSMParser parse INFO: Parsing ended.
Parsed 1741018051 B in 0 d 04:44:51.
16:20 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:44:55; Committed up to line 22892339; Throughput 50.5 entities/s.
16:20 osm2postgis.core.Monitor run INFO: Cumulative: public.osm_nodes:created=7553768 public.osm_relations:created=536 public.osm
ways:created=534564
16:20 osm2postgis.core.Monitor run CONFIG: JVM 2.7/15.6 MiB (82.5 % used); In-memory queue 1674.
16:20 tgis.core.PostGISBuilder generate INFO: Generating PostGIS geometry layers and routing topology.
16:20 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:45:10; Committed up to line 22920836; Throughput 111.6 entities/s.
16:20 osm2postgis.core.Monitor run INFO: Cumulative: public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.os
_ways:created=534564
16:20 osm2postgis.core.Monitor run CONFIG: JVM 4.1/15.6 MiB (73.5 % used).
16:21 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:45:25; Committed up to line 22920836; Throughput 0.0 entities/s.
16:21 osm2postgis.core.Monitor run INFO: Cumulative: public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.os
_ways:created=534564
16:22 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n
JOIN public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN ? AND ? ORDER BY n.id,sequence;
16:22 ostgis.dao.WayNodeCursor <init> FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS w ON
.id=w.id WHERE status=1 AND n.id BETWEEN '2066' AND '100000' ORDER BY n.id,sequence
16:22 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:22 osm2postgis.core.Monitor run CONFIG: JVM 4.1/15.6 MiB (73.6 % used).
16:22 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT k,v FROM public.osm_way_tags WHERE id=?;
16:22 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT nd,crossed,geom FROM (SELECT nd,count(*) AS cro
sed FROM public.osm_way_nodes WHERE nd IN (SELECT nd FROM public.osm_way_nodes WHERE id=?) GROUP BY nd) AS wn LEFT JOIN public.os
_nodes ON nd=public.osm_nodes.id;
16:22 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:46:49; Committed up to line 22920836; Throughput 0.0 entities/s.
16:22 osm2postgis.core.Monitor run INFO: Cumulative: public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.os
_ways:created=534564
16:28 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:28 osm2postgis.core.Monitor run CONFIG: JVM 4.0/15.6 MiB (74.3 % used).
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement DELETE FROM public.navigation_motor WHERE way=?;
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.navigation_motor (way,source,target
cost,reverse_cost,x1,y1,x2,y2,rule,to_cost,length,geom) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?);
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT lastval() FROM public.seq_navigation_motor_id;
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement UPDATE public.human_built SET geom=?,sym1=?,sym2=?,sym
=?,name=? WHERE id=?;
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.human_built (id,sym1,sym2,sym3,name
geom) VALUES (?,?,?,?,?,?);
16:28 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement UPDATE public.osm_ways SET status=? WHERE id=?;
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '100001' AND '200000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '200001' AND '300000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '300001' AND '400000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '400001' AND '500000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '500001' AND '600000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '600001' AND '700000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '700001' AND '800000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '800001' AND '900000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '900001' AND '1000000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1000001' AND '1100000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1100001' AND '1200000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1200001' AND '1300000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1300001' AND '1400000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1400001' AND '1500000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1500001' AND '1600000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1600001' AND '1700000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1700001' AND '1800000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1800001' AND '1900000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '1900001' AND '2000000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2000001' AND '2100000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2100001' AND '2200000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2200001' AND '2300000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2300001' AND '2400000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2400001' AND '2500000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2500001' AND '2600000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2600001' AND '2700000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2700001' AND '2800000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2800001' AND '2900000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '2900001' AND '3000000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3000001' AND '3100000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3100001' AND '3200000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3200001' AND '3300000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3300001' AND '3400000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3400001' AND '3500000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3500001' AND '3600000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3600001' AND '3700000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3700001' AND '3800000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3800001' AND '3900000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '3900001' AND '4000000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4000001' AND '4100000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4100001' AND '4200000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4200001' AND '4300000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4300001' AND '4400000' ORDER BY n.id,sequence
16:28 ostgis.dao.WayNodeCursor nextInterval FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS
w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4400001' AND '4500000' ORDER BY n.id,sequence
16:28 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:53:17; Committed up to line 22920836; Throughput 0.0 entities/s.
16:28 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=1 public.navigation_motor:created=2 public.osm_no
es:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:28 osm2postgis.core.Monitor run CONFIG: JVM 3.6/15.6 MiB (76.8 % used).
16:29 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:53:32; Committed up to line 22920836; Throughput 0.0 entities/s.
16:29 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=1 public.navigation_motor:created=2 public.osm_no
es:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:35 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:35 osm2postgis.core.Monitor run CONFIG: JVM 3.6/15.6 MiB (76.8 % used).
16:35 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 04:59:45; Committed up to line 22920836; Throughput 0.0 entities/s.
16:35 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=2 public.navigation_motor:created=7 public.osm_no
es:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:35 osm2postgis.core.Monitor run CONFIG: JVM 3.4/15.6 MiB (78.1 % used).
16:35 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:00:00; Committed up to line 22920836; Throughput 0.0 entities/s.
16:35 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=2 public.navigation_motor:created=7 public.osm_no
es:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:39 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:39 osm2postgis.core.Monitor run CONFIG: JVM 3.4/15.6 MiB (78.2 % used).
16:40 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:04:27; Committed up to line 22920836; Throughput 0.0 entities/s.
16:40 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=3 public.navigation_motor:created=10 public.osm_n
des:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:40 osm2postgis.core.Monitor run CONFIG: JVM 3.3/15.6 MiB (78.9 % used).
16:40 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:04:42; Committed up to line 22920836; Throughput 0.0 entities/s.
16:40 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=3 public.navigation_motor:created=10 public.osm_n
des:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:45 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:45 osm2postgis.core.Monitor run CONFIG: JVM 3.3/15.6 MiB (79.0 % used).
16:45 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement DELETE FROM public.navigation_foot WHERE way=?;
16:45 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.navigation_foot (way,source,target,
ost,reverse_cost,x1,y1,x2,y2,rule,to_cost,length,geom) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?);
16:45 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT lastval() FROM public.seq_navigation_foot_id;
16:45 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:09:52; Committed up to line 22920836; Throughput 0.0 entities/s.
16:45 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=4 public.navigation_foot:created=4 public.navigat
on_motor:created=14 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:45 osm2postgis.core.Monitor run CONFIG: JVM 3.1/15.6 MiB (80.3 % used).
16:45 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:10:08; Committed up to line 22920836; Throughput 0.0 entities/s.
16:45 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=4 public.navigation_foot:created=4 public.navigat
on_motor:created=14 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:49 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:49 osm2postgis.core.Monitor run CONFIG: JVM 3.0/15.6 MiB (80.4 % used).
16:50 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:14:33; Committed up to line 22920836; Throughput 0.0 entities/s.
16:50 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=7 public.navigation_foot:created=6 public.navigat
on_motor:created=17 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:50 osm2postgis.core.Monitor run CONFIG: JVM 2.8/15.6 MiB (81.7 % used).
16:50 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:14:48; Committed up to line 22920836; Throughput 0.0 entities/s.
16:50 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=7 public.navigation_foot:created=6 public.navigat
on_motor:created=17 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:55 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
16:55 osm2postgis.core.Monitor run CONFIG: JVM 2.8/15.6 MiB (81.8 % used).
16:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:20:09; Committed up to line 22920836; Throughput 0.0 entities/s.
16:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=8 public.navigation_foot:created=6 public.navigat
on_motor:created=24 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
16:55 osm2postgis.core.Monitor run CONFIG: JVM 2.6/15.6 MiB (83.1 % used).
16:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:20:24; Committed up to line 22920836; Throughput 0.0 entities/s.
16:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=8 public.navigation_foot:created=6 public.navigat
on_motor:created=24 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:00 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
17:00 osm2postgis.core.Monitor run CONFIG: JVM 2.6/15.6 MiB (83.2 % used).
17:01 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:25:29; Committed up to line 22920836; Throughput 0.0 entities/s.
17:01 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=10 public.navigation_foot:created=9 public.naviga
ion_motor:created=29 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:01 osm2postgis.core.Monitor run CONFIG: JVM 2.5/15.6 MiB (83.9 % used).
17:01 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:25:44; Committed up to line 22920836; Throughput 0.0 entities/s.
17:01 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=10 public.navigation_foot:created=9 public.naviga
ion_motor:created=29 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:05 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
17:05 osm2postgis.core.Monitor run CONFIG: JVM 2.5/15.6 MiB (84.0 % used).
17:05 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:29:45; Committed up to line 22920836; Throughput 0.0 entities/s.
17:05 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=11 public.navigation_foot:created=9 public.naviga
ion_motor:created=31 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:05 osm2postgis.core.Monitor run CONFIG: JVM 2.4/15.6 MiB (84.7 % used).
17:05 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:30:01; Committed up to line 22920836; Throughput 0.0 entities/s.
17:05 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=11 public.navigation_foot:created=9 public.naviga
ion_motor:created=31 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:09 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
17:09 osm2postgis.core.Monitor run CONFIG: JVM 2.4/15.6 MiB (84.8 % used).
17:10 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 05:34:29; Committed up to line 22920836; Throughput 0.0 entities/s.
17:10 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=12 public.navigation_foot:created=13 public.navig
tion_motor:created=35 public.osm_nodes:created=7553768 public.osm_relations:created=2210 public.osm_ways:created=534564
17:10 osm2postgis.core.Monitor run CONFIG: JVM 2.3/15.6 MiB (85.5 % used).

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-04

Okay, Bruce, thanks for the interesting results. The symptoms indicate that some of the more demanding queries may be running without using the indexes designed for those queries or be otherwise running 'less than optimally'.

Have you already tried VACUUM ANALYZE on that database (all tables)? If PostgreSQL doesn't have all the stats it needs, it may be planning wrong.

Here are some starting points to help analyzing this:

http://wiki.postgresql.org/wiki/FAQ#Why_are_my_queries_slow.3F_Why_don.27t_they_use_my_indexes.3F
http://openacs.org/forums/message-view?message_id=63361

Even without the above, using the EXPLAIN command we should be able to analyze which queries have a bad query plan.

For example, when I run the EXPLAIN on the final query (from the logs you posted) before it starts grinding:

EXPLAIN SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4400001' AND '4500000' ORDER BY n.id,sequence;

QUERY PLAN
-----------------------------------------------------------------------------------------------------------
Merge Join (cost=0.00..1483209.16 rows=491069 width=20)
Merge Cond: ("outer".id = "inner".id)
-> Index Scan using osm_way_nodes_pkey on osm_way_nodes n (cost=0.00..656531.72 rows=491069 width=20)
Index Cond: ((id >= 4400001::bigint) AND (id <= 4500000::bigint))
-> Index Scan using osm_ways_pkey on osm_ways w (cost=0.00..801294.88 rows=12448907 width=8)
Filter: (status = 1)
(6 rows)

The above results from my database shows that it's first performing an index scan on the osm_way_nodes, then joining the osm_ways table again with an index scan and filtering by the status field.

By the way, this is the query that I had to partition earlier because it was running too slow as a full query. That's why I added the ID range limits -- no more than an interval of 100000 id's per query.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-04

Maybe to help run your tests quicker, now that you have built the database, you can interrupt and start again on the same database with the command line option: -p f,t
This way you don't have to wait for the initial import phases (-p c,n,w,r) every time you test the -p f,t phases. This particular problem must be in the features/topology phase, so we don't neet to rerun changesets/nodes/ways/relations to debug this.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-05

Sakari,

Thanks for the insight, and your patience. I ran the 'explain' query against the maryland database (which is still building), and here is the result:

md_routing=# EXPLAIN SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN
public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4400001' AND
'4500000' ORDER BY n.id,sequence;
QUERY PLAN

--------------------------------------------------------------------------------
------------------------
Nested Loop (cost=0.00..45305.34 rows=7267 width=20)
-> Index Scan using osm_way_nodes_pkey on osm_way_nodes n (cost=0.00..12190
.50 rows=7267 width=20)
Index Cond: ((id >= 4400001::bigint) AND (id <= 4500000::bigint))
-> Index Scan using osm_ways_pkey on osm_ways w (cost=0.00..4.54 rows=1 wid
th=8)
Index Cond: (w.id = n.id)
Filter: (w.status = 1)
(6 rows)

md_routing=#
-----

I see there are differences from what you get, notably the lack of 'Merge Join' and 'Merge Cond' entries, replaced by 'nested loop.'

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-05

I terminated my current install and ran a Full vacumm analze using PGAdmin III. The results of the test query are essentially the same, i.e. nested loop:

md_routing=# EXPLAIN SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN
public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4400001' AND
'4500000' ORDER BY n.id,sequence;
QUERY PLAN

--------------------------------------------------------------------------------
------------------------
Nested Loop (cost=0.00..45048.54 rows=7222 width=20)
-> Index Scan using osm_way_nodes_pkey on osm_way_nodes n (cost=0.00..12120
.79 rows=7222 width=20)
Index Cond: ((id >= 4400001::bigint) AND (id <= 4500000::bigint))
-> Index Scan using osm_ways_pkey on osm_ways w (cost=0.00..4.55 rows=1 wid
th=8)
Index Cond: (w.id = n.id)
Filter: (w.status = 1)
(6 rows)

Also, re-running osm2postgis using -p f,t indicates the same throughput.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-05

The plot thickens. I commented out all of the custom postgresql.conf settings leaving things to just the defaults. Here is what I get when I run the explain query:

md_routing=# EXPLAIN SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN
public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '4400001' AND
'4500000' ORDER BY n.id,sequence;
QUERY PLAN

--------------------------------------------------------------------------------
------------------------------
Sort (cost=49850.84..49868.90 rows=7222 width=20)
Sort Key: n.id, n.sequence
-> Hash Join (cost=35110.72..49387.98 rows=7222 width=20)
Hash Cond: (n.id = w.id)
-> Index Scan using osm_way_nodes_pkey on osm_way_nodes n (cost=0.00.
.12120.79 rows=7222 width=20)
Index Cond: ((id >= 4400001::bigint) AND (id <= 4500000::bigint))
-> Hash (cost=27062.05..27062.05 rows=490534 width=8)
-> Seq Scan on osm_ways w (cost=0.00..27062.05 rows=490534 widt
h=8)
Filter: (status = 1)
(9 rows)
----
Re-running osm2postgis with -p f,t flag shows substantially higher throughput:

10:53 stgis.core.PostGISWriter run FINE: Writing started
10:53 osm2postgis.core.Monitor run INFO: Time elapsed 14704 d 14:53:07.
10:53 osm2postgis.core.Monitor run INFO: Cumulative: nothing.
10:53 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
10:53 osm2postgis.core.Monitor run CONFIG: JVM 14.3/15.5 MiB (8.0 % used).
10:53 tgis.core.PostGISBuilder generate INFO: Generating PostGIS geometry layers and routing topology.
10:53 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:00:15; Throughput/s 0.0 lines = 0.0 entities.
10:53 osm2postgis.core.Monitor run INFO: Cumulative: nothing.
10:54 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT n.id,nd,sequence FROM public.osm_way_nod
es AS n JOIN public.osm_ways AS w ON n.id=w.id WHERE status=1 AND n.id BETWEEN ? AND ? ORDER BY n.id,sequence;
10:54 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
10:54 osm2postgis.core.Monitor run CONFIG: JVM 14.3/15.5 MiB (8.0 % used).
10:54 ostgis.dao.WayNodeCursor <init> FINER: SELECT n.id,nd,sequence FROM public.osm_way_nodes AS n JOIN public.osm_ways A
S w ON n.id=w.id WHERE status=1 AND n.id BETWEEN '5968513' AND '6000000' ORDER BY n.id,sequence
10:54 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT k,v FROM public.osm_way_tags WHERE id=?;

10:54 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT nd,crossed,geom FROM (SELECT nd,count(*)
AS crossed FROM public.osm_way_nodes WHERE nd IN (SELECT nd FROM public.osm_way_nodes WHERE id=?) GROUP BY nd) AS wn LEFT
JOIN public.osm_nodes ON nd=public.osm_nodes.id;
10:54 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:01:29; Throughput/s 0.0 lines = 0.0 entities.
10:54 osm2postgis.core.Monitor run INFO: Cumulative: nothing.
10:54 postgis.dao.OutputTarget keepAlive FINE: The database connection is alive.
10:54 osm2postgis.core.Monitor run CONFIG: JVM 14.2/27.1 MiB (47.7 % used).
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement DELETE FROM public.navigation_motor WHERE way=?
;
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.navigation_motor (way,source
,target,cost,reverse_cost,x1,y1,x2,y2,rule,to_cost,length,geom) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?);
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT lastval() FROM public.seq_navigation_mot
or_id;
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement DELETE FROM public.navigation_foot WHERE way=?;

10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.navigation_foot (way,source,
target,cost,reverse_cost,x1,y1,x2,y2,rule,to_cost,length,geom) VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?);
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT lastval() FROM public.seq_navigation_foo
t_id;
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement SELECT geom FROM public.osm_nodes WHERE id=?;
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement UPDATE public.human_built SET geom=?,sym1=?,sym
2=?,sym3=?,name=? WHERE id=?;
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement INSERT INTO public.human_built (id,sym1,sym2,sy
m3,name,geom) VALUES (?,?,?,?,?,?);
10:55 postgis.dao.OutputTarget cacheableStatement FINER: Caching statement UPDATE public.osm_ways SET status=? WHERE id=?;

10:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:02:08; Throughput/s 0.0 lines = 4.3 entities.
10:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=23 public.navigation_foot:created=72 publi
c.navigation_motor:created=72
10:55 osm2postgis.core.Monitor run CONFIG: JVM 10.8/27.1 MiB (60.2 % used).
10:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:02:23; Throughput/s 0.0 lines = 11.2 entities.
10:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=60 public.navigation_foot:created=138 publ
ic.navigation_motor:created=138
10:55 osm2postgis.core.Monitor run CONFIG: JVM 13.4/27.1 MiB (50.5 % used).
10:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:02:38; Throughput/s 0.0 lines = 6.5 entities.
10:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=76 public.navigation_foot:created=179 publ
ic.navigation_motor:created=179
10:55 osm2postgis.core.Monitor run CONFIG: JVM 11.5/27.1 MiB (57.4 % used).
10:55 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:02:53; Throughput/s 0.0 lines = 11.0 entities.
10:55 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=107 public.navigation_foot:created=246 pub
lic.navigation_motor:created=246
10:55 osm2postgis.core.Monitor run CONFIG: JVM 8.3/27.1 MiB (69.2 % used).
10:56 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:03:08; Throughput/s 0.0 lines = 9.1 entities.
10:56 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=123 public.navigation_foot:created=306 pub
lic.navigation_motor:created=306
10:56 osm2postgis.core.Monitor run CONFIG: JVM 13.3/27.1 MiB (50.7 % used).
10:56 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:03:23; Throughput/s 0.0 lines = 15.4 entities.
10:56 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=140 public.navigation_foot:created=413 pub
lic.navigation_motor:created=413
10:56 osm2postgis.core.Monitor run CONFIG: JVM 9.4/27.1 MiB (65.3 % used).
10:56 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:03:38; Throughput/s 0.0 lines = 10.3 entities.
10:56 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=172 public.navigation_foot:created=474 pub
lic.navigation_motor:created=474
10:56 osm2postgis.core.Monitor run CONFIG: JVM 13.9/27.1 MiB (48.6 % used).
10:56 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:03:53; Throughput/s 0.0 lines = 5.5 entities.
10:56 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=191 public.navigation_foot:created=506 pub
lic.navigation_motor:created=506
10:56 osm2postgis.core.Monitor run CONFIG: JVM 12.4/27.1 MiB (54.2 % used).
10:57 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:04:08; Throughput/s 0.0 lines = 10.5 entities.
10:57 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=212 public.navigation_foot:created=574 pub
lic.navigation_motor:created=574
10:57 osm2postgis.core.Monitor run CONFIG: JVM 9.7/27.1 MiB (64.0 % used).
10:57 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:04:23; Throughput/s 0.0 lines = 7.7 entities.
10:57 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=229 public.navigation_foot:created=623 pub
lic.navigation_motor:created=623
10:57 osm2postgis.core.Monitor run CONFIG: JVM 7.6/27.1 MiB (71.8 % used).
10:57 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:04:38; Throughput/s 0.0 lines = 12.2 entities.
10:57 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=260 public.navigation_foot:created=699 pub
lic.navigation_motor:created=699
10:57 osm2postgis.core.Monitor run CONFIG: JVM 11.6/27.1 MiB (57.0 % used).
10:57 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:04:53; Throughput/s 0.0 lines = 5.5 entities.
10:57 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=273 public.navigation_foot:created=734 pub
lic.navigation_motor:created=734
10:57 osm2postgis.core.Monitor run CONFIG: JVM 10.1/27.1 MiB (62.7 % used).
10:58 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:05:08; Throughput/s 0.0 lines = 6.8 entities.
10:58 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=287 public.navigation_foot:created=778 pub
lic.navigation_motor:created=778
10:58 osm2postgis.core.Monitor run CONFIG: JVM 8.3/27.1 MiB (69.4 % used).
10:58 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:05:23; Throughput/s 0.0 lines = 8.1 entities.
10:58 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=304 public.navigation_foot:created=830 pub
lic.navigation_motor:created=830
10:58 osm2postgis.core.Monitor run CONFIG: JVM 13.7/27.1 MiB (49.3 % used).
10:58 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:05:38; Throughput/s 0.0 lines = 9.2 entities.
10:58 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=334 public.navigation_foot:created=884 pub
lic.navigation_motor:created=884
10:58 osm2postgis.core.Monitor run CONFIG: JVM 11.1/27.1 MiB (59.0 % used).
10:58 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:05:53; Throughput/s 0.0 lines = 6.5 entities.
10:58 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=353 public.navigation_foot:created=923 pub
lic.navigation_motor:created=923
10:58 osm2postgis.core.Monitor run CONFIG: JVM 9.3/27.1 MiB (65.8 % used).
10:59 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:06:08; Throughput/s 0.0 lines = 20.1 entities.
10:59 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=384 public.navigation_foot:created=1058 pu
blic.navigation_motor:created=1058
10:59 osm2postgis.core.Monitor run CONFIG: JVM 11.7/27.1 MiB (56.8 % used).
10:59 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:06:23; Throughput/s 0.0 lines = 9.9 entities.
10:59 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=415 public.navigation_foot:created=1117 pu
blic.navigation_motor:created=1117
10:59 osm2postgis.core.Monitor run CONFIG: JVM 8.8/27.1 MiB (67.7 % used).
10:59 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:06:38; Throughput/s 0.0 lines = 7.9 entities.
10:59 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=463 public.navigation_foot:created=1207 pu
blic.navigation_motor:created=1207
10:59 osm2postgis.core.Monitor run CONFIG: JVM 14.2/27.1 MiB (47.5 % used).
11:00 osm2postgis.core.Monitor run INFO: Time elapsed 0 d 00:07:03; Throughput/s 0.0 lines = 11.4 entities.
11:00 osm2postgis.core.Monitor run INFO: Cumulative: public.human_built:created=483 public.navigation_foot:created=1284 pu
blic.navigation_motor:created=1284
11:00 osm2postgis.core.Monitor run CONFIG: JVM 9.1/27.1 MiB (66.5 % used).

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-06

Ok, the different query plan results may suggest that we are on to something to solve this. It's very useful for me to see how this thing works (or doesn't work) in other environments, so I'm very much interested in what is happening here.

Again, they want me elsewhere, but I'll look into this more sometime this week.

By the way, I'm not sure if the best configuration parameters for our PostgreSQL versions are exactly the same, so you would need to do some reading for each parameter and specific instructions for your version if you really wanted to optimize it. However, if the problem is with statistics and (VACUUM ANALYZE), then the default configuration might still work just fine. I have to go now, so I'll get back in a few days.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-08

labels: 1325779 --> Map feature recognition

priority: 5 --> 6

assigned_to: nobody --> sakaal
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-08

I can now confirm this bug. My full planet.osm import run finally got to the next phase and basically hanged so the symptoms are the same. I can now reproduce it, so debug can really start.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-09

Update: I ran the discrete 'explain' sql query you sent on my x64 machine, and the result came back with a pair of nested loops. I tried playing with some of the postgres tuneable parameters with a server restart in between to no effect. I then tried a full vacuum, and after that started seeing the hash joins etc instead of the loops (I assume that's better...). However, in terms of an overall perf boost, it hasn't seemed to have helped- things are still grinding along slowly.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-11

I have now recognized at least one obvious bug in the design of WayNodeCursor class SQL query design. Unfortunately I'm too busy to fix it immediately and there is no easy workaround. The class needs to be rewritten and made simpler, i.e. to iterate the data first by Ways (having status=1) and then by nodes. Now it tries to iterate directly by way nodes, which doesn't work well with the status flag that is in a different table. I will rewrite it some day next week.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-25

I have made some advance debugging this. The PostgreSQL query planner seems to function rather poorly with anything but the simplest partial indexes. So, a lot of time has gone into working around the PostgreSQL oddities. Basically this problem seems to be caused by the status column that is used to target operations on those rows of the database that have changed.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-25

Sorry it took so long this time, but I have now released revision 83 with a fix that seems to work in my quick tests. Of course more testing is still needed, but I decided to release it already because it's definitely working better than the previous release.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sakari A. Maaranen - 2010-04-25

status: open --> open-fixed
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-26

I kicked off a test of rev 83 on two machines using maryland.osm. Last time it took about 12 days to run its course on the slower machine; I'll let you know how this one goes.

Also, I've benchmarked some shortest_path_shooting_star queries using the same dataset. On the duo-core XP box, queries take about 2.5 mins. On my I7-520, it's 38 seconds.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Nobody/Anonymous - 2010-04-27

Oh, did you start the test from scratch, meaning: dropped any existing tables? The new release adds an index that won't be present if you rerun the test on an existing database. So, if you really want to test it, you should let it create all the tables again.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-27

Sakari,

I cleaned everything out prior, thanks. I'll be back with a report in another day.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-28

Sakari, the test run on my duo-core Xp machine bombed about 1/4 of the way into the install. I will attach the log, but here is a screen cap from the command window:

17:14 osm2postgis.core.Monitor run CONFIG: JVM 46.3/82.9 MiB (44.2 % used).
17:14 osm2postgis.core.Monitor run INFO: Time elapsed 1 d 03:27:02; Committed up to line 24043321; Throughput/
s 0.0 lines = 4.9 entities.
17:14 osm2postgis.core.Monitor run INFO: Cumulative: public.anomaly:created=199 public.human_built:created=114
542 public.human_landuse:created=52 public.navigation_aero:created=41 public.navigation_foot:created=268013 pu
blic.navigation_motor:created=270182 public.navigation_nautical:created=1 public.osm_nodes:created=7855168 pub
lic.osm_nodes:ignored=1 public.osm_nodes:updated=19 public.osm_relations:created=2320 public.osm_relations:ign
ored=2 public.osm_relations:updated=2 public.osm_ways:created=564180 public.osm_ways:updated=9 public.physiogr
aphy_surface:created=1 public.physiography_water:created=3
17:14 osm2postgis.core.Monitor run CONFIG: JVM 44.8/82.9 MiB (46.0 % used).
17:14 osm2postgis.core.Monitor run INFO: Time elapsed 1 d 03:27:17; Committed up to line 24043321; Throughput/
s 0.0 lines = 9.9 entities.
17:14 osm2postgis.core.Monitor run INFO: Cumulative: public.anomaly:created=199 public.human_built:created=114
554 public.human_landuse:created=52 public.navigation_aero:created=41 public.navigation_foot:created=268081 pu
blic.navigation_motor:created=270250 public.navigation_nautical:created=1 public.osm_nodes:created=7855168 pub
lic.osm_nodes:ignored=1 public.osm_nodes:updated=19 public.osm_relations:created=2320 public.osm_relations:ign
ored=2 public.osm_relations:updated=2 public.osm_ways:created=564180 public.osm_ways:updated=9 public.physiogr
aphy_surface:created=1 public.physiography_water:created=3
17:14 osm2postgis.core.Monitor run CONFIG: JVM 41.9/82.9 MiB (49.4 % used).
17:15 stgis.core.PostGISWriter run SEVERE: Problems writing.
org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:283)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:271)
at net.sourceforge.osm2postgis.dao.WayDAO.readSegmentNodes(WayDAO.java:491)
at net.sourceforge.osm2postgis.model.OSMWay.split(OSMWay.java:220)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generateTopology(PostGISBuilder.java:223)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generateWay(PostGISBuilder.java:193)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generate(PostGISBuilder.java:150)
at net.sourceforge.osm2postgis.core.PostGISWriter.run(PostGISWriter.java:96)
at java.lang.Thread.run(Unknown Source)
Caused by: java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(Unknown Source)
at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:259)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1620)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
... 10 more
org.postgresql.util.PSQLException: An I/O error occured while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:283)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:479)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:367)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:271)
at net.sourceforge.osm2postgis.dao.WayDAO.readSegmentNodes(WayDAO.java:491)
at net.sourceforge.osm2postgis.model.OSMWay.split(OSMWay.java:220)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generateTopology(PostGISBuilder.java:223)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generateWay(PostGISBuilder.java:193)
at net.sourceforge.osm2postgis.core.PostGISBuilder.generate(PostGISBuilder.java:150)
at net.sourceforge.osm2postgis.core.PostGISWriter.run(PostGISWriter.java:96)
at java.lang.Thread.run(Unknown Source)
Caused by: java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(Unknown Source)
at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:259)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1620)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
... 10 more
17:15 stgis.core.PostGISWriter run FINE: Writing ended
17:15 stgis.core.PostGISWriter run INFO: Wrote 9074891 entities in 1 d 03:27:23 (91.8/s on average).
Wrote 9074891 entities in 1 d 03:27:23 (91.8/s on average).

e:\Vehicle Routing\osm2postgis\trunk>

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-28

rev 83 crash log

osm2postgis_rev83_crash.rar

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Bruce Drees - 2010-04-28

Something that may have played into the rev 83 problem reported earier is that I was testing a local pgrouting shortest_path_shooting_star call at about the same time. The process that executed the sql (PgAdmin query window) lost the server connection for the particular database I was using (a different one from the install taking place) as a result of the query.

Also, the test run on my Win7 machine is still running, so I'm not sure this is an osm2postgis issue.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

performance question-medium dataset

Group

Searches

Help

#12 performance question-medium dataset

Discussion