Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Extremely Slow Query Execution After Postgres 9.6 Upgrade

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.
like image 354
picmate 涅 Avatar asked Nov 05 '17 03:11

picmate 涅


1 Answers

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

like image 164
babis21 Avatar answered Oct 19 '22 01:10

babis21