Subject: Re: Delete query takes exorbitant amount of time
From: Simon Riggs <simon@2ndquadrant.com>
To: Karim A Nassar <Karim.Nassar@NAU.EDU>
Cc: Stephan Szabo <sszabo@megazone.bigpanda.com>,
 Tom Lane <tgl@sss.pgh.pa.us>,
	Christopher Kings-Lynne <chriskl@familyhealth.com.au>,
	pgsql-performance@postgresql.org
In-Reply-To: <Pine.SOL.4.21.0503280934160.831-100000@coruscant.cet.nau.edu>
References: <Pine.SOL.4.21.0503280934160.831-100000@coruscant.cet.nau.edu>
Content-Type: text/plain
Organization: 2nd Quadrant
Date: Mon, 28 Mar 2005 20:25:54 +0100
Message-Id: <1112037954.11750.903.camel@localhost.localdomain>
Mime-Version: 1.0
Content-Transfer-Encoding: 7bit

On Mon, 2005-03-28 at 09:37 -0700, Karim A Nassar wrote:
> On Mon, 28 Mar 2005, Stephan Szabo wrote:
> > > On Mon, 28 Mar 2005, Simon Riggs wrote:
> > > > run the EXPLAIN after doing
> > > > 	SET enable_seqscan = off
> 
> ...
> 
> > I think you have to prepare with enable_seqscan=off, because it
> > effects how the query is planned and prepared.
> 
> orfs=# SET enable_seqscan = off;
> SET
> orfs=# PREPARE test2(int) AS SELECT 1 from measurement where
> orfs-# id_int_sensor_meas_type = $1 FOR UPDATE;
> PREPARE
> orfs=#  EXPLAIN ANALYZE EXECUTE TEST2(1); -- non-existent
> 
> QUERY PLAN                                       
> -------------------------------------------------------------------------
>  Index Scan using measurement__id_int_sensor_meas_type_idx on measurement
>     (cost=0.00..883881.49 rows=509478 width=6) 
>     (actual time=29.207..29.207 rows=0 loops=1)
>    Index Cond: (id_int_sensor_meas_type = $1)
>  Total runtime: 29.277 ms
> (3 rows)
> 
> orfs=#  EXPLAIN ANALYZE EXECUTE TEST2(197); -- existing value
> 
> QUERY PLAN                                   
> -------------------------------------------------------------------------
>  Index Scan using measurement__id_int_sensor_meas_type_idx on measurement
>     (cost=0.00..883881.49 rows=509478 width=6) 
>     (actual time=12.903..37478.167 rows=509478 loops=1)
>    Index Cond: (id_int_sensor_meas_type = $1)
>  Total runtime: 38113.338 ms
> (3 rows)
> 

"That process starts upon the supposition that when you have eliminated
all which is impossible, then whatever remains, however improbable, must
be the truth." - Sherlock Holmes

Well, based upon the evidence so far, the Optimizer got it right:

Normal
SeqScan, value=1	elapsed= 6.4s	cost=164559
SeqScan, value=197	elapsed=28.1s	cost=164559

SeqScan=off
IndexScan, value=1	elapsed= 29ms	cost=883881
IndexScan, value=197	elapsed=38.1s	cost=883881

With SeqScan=off the index is used, proving that it has been correctly
defined for use in queries.

The FK CASCADE delete onto measurement will only be triggered by the
deletion of a real row, so the actual value will be the time taken. This
is longer than a SeqScan, so the Optimizer is correct.

My guess is that Measurement has a greatly non-uniform distribution of
values and that 197 is one of the main values. Other values exist in the
lookup table, but are very infrequently occurring in the larger table.

Karim,
Please do:

select id_int_sensor_meas_type, count(*)
from measurement
group by id_int_sensor_meas_type
order by count(*) desc;

Best Regards, Simon Riggs