6

I am seeing extremely slow processing times after a Postgres upgrade from 9.5 to 9.6 related to queries Osmosis (the command line Java application for processing OpenStreetMap data). Specifically syncing a local osm database with the master osm repo (Postgis 2.3 from 2.2). The syncing used to happen every day and took about 500 seconds on average. After the upgrade, after 48 hours, it is still not over. I notice very slow (below zero) object processing times (log record below) compared to before. I am fairly certain the problem is with the Postgres update. Can't figure out what to fix. pg_stat_activity gives the following query (currently):

UPDATE ways w 
SET linestring = ( 
    SELECT ST_MakeLine(c.geom) AS way_line 
    FROM ( 
        SELECT n.geom AS geom 
        FROM nodes n 
        INNER JOIN way_nodes wn ON n.id = wn.node_id 
        WHERE (wn.way_id = w.id) 
        ORDER BY wn.sequence_id ) c ) 
WHERE w.id IN ( 
    SELECT w.id 
    FROM ways w 
    INNER JOIN way_nodes wn ON w.id = wn.way_id 
    WHERE wn.node_id = $1 
    GROUP BY w.id )

Log record after the update:

Oct 31, 2017 12:23:59 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Osmosis Version 0.45
Oct 31, 2017 12:24:00 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Preparing pipeline.
Oct 31, 2017 12:24:00 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Launching pipeline execution.
Oct 31, 2017 12:24:00 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Pipeline executing, waiting for completion.
Oct 31, 2017 12:24:16 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022046 with action Modify, 0.06660006660006661 objects/second.
Oct 31, 2017 4:12:49 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022047 with action Modify, 7.292125918680253E-5 objects/second.
Oct 31, 2017 6:54:27 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022053 with action Modify, 1.0311411856040729E-4 objects/second.
Oct 31, 2017 9:39:22 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022056 with action Modify, 1.0106204077408672E-4 objects/second.
Nov 01, 2017 5:07:11 AM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022057 with action Modify, 3.72178939465691E-5 objects/second.
Nov 01, 2017 7:43:20 AM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 26022058 with action Modify, 1.0673723278600615E-4 objects/second.

Log record before the update:

Oct 22, 2017 11:00:01 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Osmosis Version 0.45
Oct 22, 2017 11:00:02 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Preparing pipeline.
Oct 22, 2017 11:00:02 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Launching pipeline execution.
Oct 22, 2017 11:00:02 PM org.openstreetmap.osmosis.core.Osmosis run
INFO: Pipeline executing, waiting for completion.
Oct 22, 2017 11:00:17 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 557521 with action Modify, 0.06700616456714018 objects/second.
Oct 22, 2017 11:00:22 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 49820266 with action Modify, 58.15347721822542 objects/second.
Oct 22, 2017 11:00:27 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 81804664 with action Modify, 40.64719810576164 objects/second.
Oct 22, 2017 11:00:32 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 109690032 with action Modify, 24.57577530719719 objects/second.
Oct 22, 2017 11:00:38 PM org.openstreetmap.osmosis.core.progress.v0_6.ChangeProgressLogger process
INFO: Processing Node 124684125 with action Modify, 58.35490938060148 objects/second.
JGH
  • 15,928
  • 4
  • 31
  • 48
picmate 涅
  • 3,951
  • 5
  • 43
  • 52
  • 7
    What method did you use to upgrade - pg_upgrade? If so, did you perform an ANALYZE on the database after upgrade? – harmic Nov 05 '17 at 03:26
  • Thanks for the comment. Yes. It was pg_upgrade. And no, didn't perform an ANALYZE. I'll try that. – picmate 涅 Nov 05 '17 at 12:25
  • `pg_upgrade` creates a shell script/batch file named `analyze_new_cluster` which is intended exactly for that –  Nov 07 '17 at 09:49
  • 1
    Harmic you should have made an answer like this, then we could mark it correct and upvote it for you! – Spence Nov 07 '17 at 09:55

2 Answers2

6

FYI, I came across with exactly the same issue: I upgraded pg to 9.6 from 9.4 and queries ran much slower.

I had run only vacuum, nothing changed, but then I ran analyse as @harmic suggested and runs fine now (even faster, thanks to pg 9.6 improvements :) )!

babis21
  • 1,515
  • 1
  • 16
  • 29
  • 2
    `pg_upgrade` creates a shell script/batch file named `analyze_new_cluster` which is intended exactly for that (I even think pg_upgrade tells you to run that script when it's finished) –  Nov 07 '17 at 09:49
  • This issue got me too. I didn't intentionally skip running the analyze script, but I had no idea how important it was — it sounds like something optional related to gathering performance statistics, rather than an essential task to ensure the database keeps working at an acceptable speed! – mpavey Nov 08 '17 at 17:19
0

After Postgres Upgrade you need to analyze the database for fast query plane.

To analyze the full database run the below query

ANALYZE VERBOSE  --for all database analyze

To analyze only a specific table then use this query

ANALYZE VERBOSE  [Table_name] --for particular table

query works in this Supported Versions: Current (13) / 12 / 11 / 10 / 9.6 / 9.5

reference: https://www.postgresql.org/docs/9.1/sql-analyze.html

nirav kanani
  • 47
  • 8