[GENERAL] Very slow inner join query Unacceptable latency.

[fburgess]

The SARS_ACTS table currently has 37,115,515 rowswe have indexed: idx_sars_acts_acts_run_id ON SARS_ACTS USING btree (sars_run_id)we have pk constraint on the SARS_ACTS_RUN table; sars_acts_run_pkey PRIMARY KEY (id )serverdb=# explain select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1_.ALGORITHM='SMAT';    QUERY PLAN--Aggregate  (cost=4213952.17..4213952.18 rows=1 width=0)  -> Hash Join  (cost=230573.06..4213943.93 rows=3296 width=0)   Hash Cond:  (this_.SARS_RUN_ID=tr1_.ID)   ->  Seq Scan om sars_acts this_  (cost=0.00..3844241.84 rows=37092284 width=8)   ->  Hash  (cost=230565.81..230565.81 rows=580 width=8)  -> Seq Scan on sars_acts_run tr1_  (cost=0.00..230565.81 rows=580 width=8)   Filter:  ((algorithm)::text = 'SMAT'::text)(7 rows)This query executes in approximately 5.3 minutes to complete, very very slow, our users are not happy.I did add an index on SARS_ACTS_RUN.ALGORITHM column but it didn't improve the run time. The planner just changed the "Filter:" to an "Index Scan:" improving the cost of the Seq Scan on the sars_acts_run table, but the overall run time remained the same. It seems like the bottleneck is in the Seq Scan on the sars_acts table.  -> Seq Scan on sars_acts_run tr1_  (cost=0.00..230565.81 rows=580 width=8)   Filter:  ((algorithm)::text = 'SMAT'::text)Does anyone have suggestions about how to speed it up?

Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptable latency.

[fburgess]

PostgreSQL 9.1.6 on linux


 Original Message 
Subject: Re: [PERFORM] Very slow inner join query Unacceptable latency.
From: Jaime Casanova 
Date: Tue, May 21, 2013 2:59 pm
To: Freddie Burgess 
Cc: psql performance list ,  Postgres
General 

On Tue, May 21, 2013 at 4:53 PM,   wrote:
> The SARS_ACTS table currently has 37,115,515 rows
>
> we have indexed: idx_sars_acts_acts_run_id ON SARS_ACTS USING btree
> (sars_run_id)
> we have pk constraint on the SARS_ACTS_RUN table; sars_acts_run_pkey PRIMARY
> KEY (id )
>
> serverdb=# explain select count(*) as y0_ from SARS_ACTS this_ inner join
> SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1_.ALGORITHM='SMAT';

can you please show us an EXPLAIN ANALYZE of this query (not only
EXPLAIN). please paste it in a file and attach it so it doesn't get
reformatted by the mail client.

what version of postgres is this?

--
Jaime Casanova www.2ndQuadrant.com
Professional PostgreSQL: Soporte 24x7 y capacitación
Phone: +593 4 5107566 Cell: +593 987171157


The SARS_ACTS table currently has 37,115,515 rows

I re-added the index on algorithm: idx_sars_acts_run_algorithm ON SARS_ACTS_RUN 
(algorithm)

serverdb=# explain analyze select count(*) as y0_ from SARS_ACTS this_ inner 
join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where 
tr1_.ALGORITHM='SMAT';
QUERY PLAN
--
Aggregate  (cost=3983424.05..3983424.06 rows=1 width=0) (actual 
time=1358298.003..1358298.004 rows=1 loops=1)
  -> Hash Join  (cost=44.93..3983415.81 rows=3297 width=0) (actual 
time=2593.768..1358041.205 rows 1481710 loops=1)
   Hash Cond:  (this_.SARS_RUN_ID=tr1_.ID)
   ->  Seq Scan om sars_acts this_  (cost=0.00..3844241.84 rows=37092284 
width=8) (actual time=0.026..1348954.763 rows=37461345 loops=1)
   ->  Hash  (cost=37.68..37.68 rows=580 width=8) (actual 
time=435.655..435.655 rows=441 loops=1)
 Buckets: 1024 Batches: 1 Memory Usage: 18kB
  -> Index Scan using idx_mars_track_run_algorithm on SARS_ACTS_RUN 
tr1_  (cost=0.00..37.68 rows=580 width=8) (actual time=10.580..435.273 rows 441 
loops=1)
   Index Cond:  ((algorithm)::text = 'SMAT'::text)

Total runtime: 1358298.664 ms <- 22.6383 minutes

(9 rows)


-- 
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptable latency.

[fburgess]

serverdb=# set enable_hashjoin=off;SETserverdb=# explain select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1.ALGORITHM='SMAT';    QUERY PLAN--Aggregate  (cost=7765563.69..7765563.70 rows=1 width=0)   Nested Loop  (cost=0.00..776.35 rows=3336 width=0) -> Index Scan using idx_sars_acts_run_algorithm on sars_acts_run tr1_  (cost=0.00..44.32 rows=650 width=8)   Index Cond:  ((algorithm)::text = 'SMAT'::text) -> Index Scan using idx_sars_acts_run_id_end_time on sars_acts this_  (cost=0.00..11891.29 rows=4452 width=8)   Index Cond:  (SARS_RUN_ID=tr1_.ID)(6 rows)serverdb=# \timingTIming is on.serverdb=# select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1.ALGORITHM='SMAT'; y0_--1481710(1 row)Time: 85069.416 ms < 1.4 minutes <-- not great, but much better!Subsequently, runs in the milliseconds once cached.But what negative impact is disabling hash joins?Sorry, I just executed the explain without the analyze, I'll send out the "explain analyze" next reply.thanksFreddie


 Original Message 
Subject: Re: [PERFORM] Very slow inner join query Unacceptable latency.
From: Jeff Janes 
Date: Wed, May 22, 2013 5:17 pm
To: fburg...@radiantblue.com
Cc: Jaime Casanova ,  psql performance list
,  Postgres General


On Wed, May 22, 2013 at 7:41 AM,  wrote:  PostgreSQL 9.1.6 on linux>From the numbers in your attached plan, it seems like it should be doing a nested loop from the 580 rows (it thinks) that match in SARS_ACTS_RUN against the index on sars_run_id to pull out the 3297 rows (again, it think, though it is way of there). I can't see why it would not do that. There were some planner issues in the early 9.2 releases that caused very large indexes to be punished, but I don't think those were in 9.1 Could you "set enable_hashjoin to off" and post the "explain analyze" that that gives? Cheers, Jeff  

Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptable latency.

[fburgess]

1.) Server settingmemory: 32960116kB = 32GB2.) Current Postgresql configuration settings of note in my environment.enable_hashjoin=offwork_mem = 16MB #random_page_cost-4.0 <- defaultmaintenance_work_mem=256MBshared_buffers = 8GBserverdb=# explain analyze select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1.ALGORITHM='SMAT';    QUERY PLAN--Aggregate  (cost=5714258.72..5714258.73 rows=1 width=0) (actual time=54402.148..54402.148 rows=1 loops=1) Nested Loop  (cost=0.00..5714253.25 rows=2188 width=0) (actual time=5.920..54090.676 rows=1481710 loops=1) -> Index Scan using idx_SARS_ACTS_run_algorithm on SARS_ACTS_run tr1_  (cost=0.00..32.71 rows=442 width=8) (actual time=1.423..205.256 rows=441 loops=1)  Index Cond:  ((algorithm)::text = 'SMAT'::text) -> Index Scan using idx_SARS_ACTS_run_id_end_time on SARS_ACTS this_  (cost=0.00..12874.40 rows=4296 width=8) (actual time=749..121.125 rows=3360 loops=441)  Index Cond:  (SARS_RUN_ID=tr1_.ID)Total runtime: 54402.212 ms <- 54 seconds(7 rows)3.) Setting the recommended parametersserverdb=# set work_mem='500MB';SETserverdb=# set random_page_cost=1.2;SETserverdb=# explain analyze select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1.ALGORITHM='SMAT';    QUERY PLAN--Aggregate  (cost=1754246.85..1754246.86 rows=1 width=0) (actual time=1817.644..1817.644 rows=1 loops=1)  Nested Loop  (cost=0.00..1754241.38 rows=2188 width=0) (actual time=0.135..1627.954 rows=1481710 loops=1) -> Index Scan using idx_SARS_ACTS_run_algorithm on SARS_ACTS_run tr1_  (cost=0.00..22.40 rows=442 width=8) (actual time=0.067..0.561 rows=441 loops=1)  Index Cond:  ((algorithm)::text = 'SMAT'::text) -> Index Scan using idx_SARS_ACTS_run_id_end_time on SARS_ACTS this_  (cost=0.00..3915.12 rows=4296 width=8) (actual time=0.008..2.972 rows=3360 loops=441)  Index Cond:  (SARS_RUN_ID=tr1_.ID)Total runtime: 1817.695 ms  1.8 seconds <- very good response time improvement(7 rows)4.) Now toggling the enable_hashjoin, I suspect the plan is cached, so these results may be suspect.serverdb=# set enable_hashjoin=on;SETserverdb=# explain analyze select count(*) as y0_ from SARS_ACTS this_ inner join SARS_ACTS_RUN tr1_ on this_.SARS_RUN_ID=tr1_.ID where tr1.ALGORITHM='SMAT';    QUERY PLAN--Aggregate  (cost=1754246.85..1754246.86 rows=1 width=0) (actual time=1606.683..1606.683 rows=1 loops=1)  Nested Loop  (cost=0.00..1754241.38 rows=2188 width=0) (actual time=0.136..1442.463 rows=1481710 loops=1) -> Index Scan using idx_SARS_ACTS_run_algorithm on SARS_ACTS_run tr1_  (cost=0.00..22.40 rows=442 width=8) (actual time=0.068..0.591 rows=441 loops=1)  Index Cond:  ((algorithm)::text = 'SMAT'::text) -> Index Scan using idx_SARS_ACTS_run_id_end_time on SARS_ACTS this_  (cost=0.00..3915.12 rows=4296 width=8) (actual time=0.007..2.659 rows=3360 loops=441)  Index Cond:  (SARS_RUN_ID=tr1_.ID)Total runtime: 1606.728 ms 1.6 seconds <- very good response time improvement(7 rows)Questions:Any concerns with setting these conf variables you recommended; work_mem, random_page_cost dbserver wide (in postgresql,conf)? Thanks so much!!!


 Original Message 
Subject: Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptable
latency.
From: Scott Marlowe 
Date: Thu, May 23, 2013 11:16 pm
To: fburg...@radiantblue.com
Cc: Jaime Casanova ,  psql performance list
,  Postgres General


Looking at the execution plan makes me wonder what your work_mem is
set to.  Try cranking it up to test and lowering random_page_cost:

set work_mem='500MB';
set random_page_cost=1.2;
explain analyze select ...

and see what you get.

Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptable latency.

[fburgess]

We re-tested these settings a few times after our initial test and realized that the execution time I posted was shewed, because the execution plan was cached after the initial run. Subsequent executions ran in a little over a second.
There ended up being no significant saving by setting these parameters. Un-cached the query ran in about 55 seconds. 
 

 Original Message Subject: Re: [GENERAL] [PERFORM] Very slow inner join query Unacceptablelatency.From: Scott Marlowe Date: Fri, May 24, 2013 3:03 pmTo: fburg...@radiantblue.comCc: Jaime Casanova , psql performance list, Postgres GeneralOn Fri, May 24, 2013 at 3:44 PM,  wrote:> Total runtime: 1606.728 ms 1.6 seconds <- very good response time> improvement>> (7 rows)>> Questions:>> Any concerns with setting these conf variables you recommended; work_mem,> random_page_cost dbserver wide (in postgresql,conf)?>> Thanks so much!!!Yes 500MB is pretty high especially if you have a lot of connections.Try it with it back down to 16MB and see how it does. Work mem is persort so a setting as high as 500MB can exhaust memory on the machineunder heavy load.--To understand recursion, one must first understand recursion.

[GENERAL] Evaluating query performance with caching in PostgreSQL 9.1.6

[fburgess]

Two questions Please1.) Is there any way to clear the cache so that we can ensure that when we run "explain analyze" on a query and make some minor adjustments to that query and re-execute, the plan is not cached. Since the cached plan returns runtimes that are much lower than the initial execution, so we don't know for certain the tweaks we made improved the performance of the query, without having to bounce the database?2.) I am noticing that when I look at pg_stat_activities: autovacuum is re-processing some old Partition tables way back in 2007, which are static and are essentially read-only partitions. the line item in pg_stat reads as follows: autovacuum:VACUUM public.digi_sas_y2007m07 (to prevent wraparound). Is there a way to have autovacuum skip these static type partition tables, and only process partitions that have had; Inserts, updates, or deletes attributed to them? thanks. 

[GENERAL] Upgrading from postgreSQL 9.1.6 to 9.3

[fburgess]

Are there any showstoppers/recommendations/experiences with
upgrading from Postgres 9.1.6 Postgis 1.5.3 to PostGres 9.3 and associated
PostGIS version XX on rhel 6.4 that will help the process go smoothly.thanks

Re: [GENERAL] Upgrading from postgreSQL 9.1.6 to 9.3

[fburgess]

1.) We have to upgrade four 9.1 database instances, so is using pg_upgrade still the way to go? Our prior upgrade methodology when we moved from pg 8.4.3 to 9.1.6 was to use the hard links install option. We also have our data spread across storage mediums; fiber, nas. Do these things factor in?2.) We also have to stand up a fresh install of pg 9.3 and restore the data from a 9.1.6 dump, do you recommended that you use the pg_dump or pg_dumpall?and since we have our data spread across storage locations on fiber and nas, we will have to replicate the file system structure on the target os to be identical to that of the source 9.1.6 dump file system?3.) In general if the backup takes approximately 5-7 days, will the restore to the fresh install environment take as long, or longer? Trying to gauge downtime requirements. thanks


 Original Message 
Subject: Re: [GENERAL] Upgrading from postgreSQL 9.1.6 to 9.3
From: Paul Ramsey 
Date: Thu, September 19, 2013 10:51 am
To: fburg...@radiantblue.com
Cc: pgsql-general@postgresql.org

Recommendation: do one at a time. First postgis 1.5 to 2.1, then pg 9.1 to 9.3. 
P.

-- 
Paul Ramsey
http://cleverelephant.ca
http://postgis.net


On Thursday, September 19, 2013 at 4:34 PM, fburg...@radiantblue.com wrote:

> 
> 
> Are there any showstoppers/recommendations/experiences with upgrading from Postgres 9.1.6 Postgis 1.5.3 to PostGres 9.3 and associated PostGIS version XX on rhel 6.4 that will help the process go smoothly.
> 
> 
> 
> thanks 

[GENERAL] Very slow query in PostgreSQL 9.3.3

[fburgess]

PostgreSQL 9.3.3 RHEL 6.4Total db Server memory 64GB# -# PostgreSQL configuration file# -max_connections = 100shared_buffers = 16GBwork_mem = 32MB maintenance_work_mem = 1GBseq_page_cost = 1.0   random_page_cost = 2.0    cpu_tuple_cost = 0.03  #cpu_index_tuple_cost = 0.005   #cpu_operator_cost = 0.0025 effective_cache_size = 48MBdefault_statistics_target = 100   constraint_exclusion = partition Partition table Setup-CREATE TABLE measurement (    id  bigint not null,    city_id bigint not null,    logdate date not null,    peaktemp    bigint,    unitsales   bigint,    type    bigint,    uuid    uuid,    geom    geometry);CREATE TABLE measurement_y2006m02 (    CHECK ( logdate >= DATE '2006-02-01' AND logdate < DATE '2006-03-01' )) INHERITS (measurement);CREATE TABLE measurement_y2006m03 (    CHECK ( logdate >= DATE '2006-03-01' AND logdate < DATE '2006-04-01' )) INHERITS (measurement);...CREATE TABLE measurement_y2007m11 (    CHECK ( logdate >= DATE '2007-11-01' AND logdate < DATE '2007-12-01' )) INHERITS (measurement);CREATE TABLE measurement_y2007m12 (    CHECK ( logdate >= DATE '2007-12-01' AND logdate < DATE '2008-01-01' )) INHERITS (measurement);CREATE TABLE measurement_y2008m01 (    CHECK ( logdate >= DATE '2008-01-01' AND logdate < DATE '2008-02-01' )) INHERITS (measurement);Partition measurement_y2007m12 contains 38,261,732 rowsIndexes on partition measurement_y2007m12:    "pkey_measurement_y2007m12" PRIMARY KEY, btree (id), tablespace "measurement_y2007"    "idx_measurement_uuid_y2003m12" btree (uuid), tablespace "measurement_y2007"    "idx_measurement_type_y2003m12" btree (type), tablespace "measurement_y2007"    "idx_measurement_city_y2003m12" btree (city_id), tablespace "measurement_y2007"    "idx_measurement_logdate_y2003m12" btree (logdate), tablespace "measurement_y2007"    "sidx_measurement_geom_y2003m12" gist (geom), tablespace "measurement_y2007"*** Problem Query *** explain (analyze on, buffers on) Select * from measurement this_   where this_.logdate between '2007-12-19 23:38:41.22'::timestamp and '2007-12-20 08:01:04.22'::timestamp    and this_.city_id=25183 order by this_.logdate asc, this_.peaktemp asc, this_.unitsales asc limit 1;  QUERY PLAN   --- Limit  (cost=33849.98..33855.15 rows=2068 width=618) (actual time=51710.803..51714.266 rows=1 loops=1)   Buffers: shared hit=25614 read=39417   ->  Sort  (cost=33849.98..33855.15 rows=2068 width=618) (actual time=51710.799..51712.924 rows=1 loops=1) Sort Key: this_.logdate, this_.unitsales Sort Method: top-N heapsort  Memory: 15938kB Buffers: shared hit=25614 read=39417 ->  Append  (cost=0.00..33736.09 rows=2068 width=618) (actual time=50.210..50793.589 rows=312046 loops=1)   Buffers: shared hit=25608 read=39417   ->  Seq Scan on measurement this_  (cost=0.00..0.00 rows=1 width=840) (actual time=0.002..0.002 rows=0 loops=1) Filter: ((logdate >= '2007-12-19 23:38:41.22'::timestamp without time zone) AND (logdate <= '2007-12-20 08:01:04.22'::timestamp without time zone) AND (city_id = 25183))   ->  Index Scan using idx_measurement_city_y2007m12 on measurement_y2007m12 this__1  (cost=0.56..33736.09 rows=2067 width=618) (actual time=50.206..50731.637 rows=312046 loops=1) Index Cond: (city_id = 25183) Filter:  ((logdate >= '2007-12-19 23:38:41.22'::timestamp without time zone) AND (logdate <= '2007-12-20 08:01:04.22'::timestamp without time zone)) Buffers: shared hit=25608 read=39417 Total runtime: 51717.639 ms   <--- *** unacceptable ***(15 rows)  Total Rows meeting query criteria-Select count(*) from measurement this_ where this_.logdate between '2007-12-19 23:38:41.22'::timestamp and '2007-12-20 08:01:04.22'::timestamp and this_.city_id=25183;count--312046Total Rows in the partition table referenced--Select
 count(*) from measurement_y2007m12;  count-38261732Does anyone know how to speed up this query? I removed the order by clause and that significantly reduced the run time to approx. 2000-3000 ms. This query is being recorded repeatedly in our logs and executes very slowly for our UI users from 12000 ms thru 68000 msAny suggestions would be a