Обсуждение: please help with the explain analyze plan
Dear friends, I have explain analyze of two queries explain analyze SELECT count(*) from general.rfis where 1=1 and inquiry_type = 'BUY' and receiver_uid=1320721; (7 ms) http://pastebin.com/m5297e03c explain analyze SELECT count(*) from general.rfis where 1=1 and inquiry_type = 'BUY' and receiver_uid=1320721 generated_date >= 2251 and ; (80 secs) http://pastebin.com/d1e4bdea7 The table general.rfis is partitioned on generated_date and the condition generated_date >= 2251 was added with the intention to limit the number of (date based) partitions that would be searched by the query using the constraint exclusion facility. however as evident the query has become very slow as a result of this condition (even on primed caches). can anyone kindly explain why the result was so counter intuitive ? In particular where is most of the (80828.438 ms) spent on the plan http://pastebin.com/d1e4bdea7 (reference to actual line number is appreciated) structure of a typical partition (abridged) Table "rfi_partitions.rfis_part_2009_01" Column | Type | Modifiers -----------------------+------------------------+--------------------------------------------------------------- rfi_id | integer | not null default nextval('general.rfis_rfi_id_seq'::regclass) sender_uid | integer | not null receiver_uid | integer | not null subject | character varying(100) | not null message | text | not null inquiry_type | character varying(50) | default 'BUY'::character varying inquiry_source | character varying(30) | not null generated_date | integer | not null default general.current_date_id() Indexes: "rfis_part_2009_01_pkey" PRIMARY KEY, btree (rfi_id) "rfis_part_2009_01_generated_date" btree (generated_date) "rfis_part_2009_01_receiver_uid" btree (receiver_uid) CLUSTER "rfis_part_2009_01_sender_uid" btree (sender_uid) Check constraints: "rfis_part_2009_01_generated_date_check" CHECK (generated_date >= 3289 AND generated_date <= 3319) "rfis_part_2009_01_rfi_id_check" CHECK (rfi_id >= 12344252 AND rfi_id <= 12681399) Inherits: rfis regds rajesh kumar mallah.
Both queries are using your uid index on each of the partitions not generated_date, it's doing the generated_date with
afilter on most of the partitions.
This is except for on partition part_2006_02 in the second query where it uses your generated date index - and that
takesthe 80 secs.
-> Index Scan using rfis_part_2006_02_generated_date on rfis_part_2006_02 rfis (cost=0.00..6.45 rows=1
width=0)(actual time=80827.207..80827.207 rows=0 loops=1)
Also the second query appears to go through a few more partitions than the first, i.e. part_2001_2004 and part_1005
--- On Wed, 11/2/09, Rajesh Kumar Mallah <mallah.rajesh@gmail.com> wrote:
> From: Rajesh Kumar Mallah <mallah.rajesh@gmail.com>
> Subject: [PERFORM] please help with the explain analyze plan
> To: pgsql-performance@postgresql.org
> Date: Wednesday, 11 February, 2009, 10:58 AM
> Dear friends,
>
> I have explain analyze of two queries
>
> explain analyze SELECT count(*) from general.rfis where
> 1=1 and
> inquiry_type = 'BUY' and receiver_uid=1320721;
> (7 ms)
> http://pastebin.com/m5297e03c
>
> explain analyze SELECT count(*) from general.rfis where
> 1=1 and
> inquiry_type = 'BUY' and receiver_uid=1320721
> generated_date >=
> 2251 and ;
> (80 secs)
> http://pastebin.com/d1e4bdea7
>
>
> The table general.rfis is partitioned on generated_date and
> the
> condition generated_date >= 2251
> was added with the intention to limit the number of (date
> based)
> partitions that would be searched
> by the query using the constraint exclusion facility.
> however as
> evident the query has become very
> slow as a result of this condition (even on primed caches).
>
> can anyone kindly explain why the result was so counter
> intuitive ?
>
> In particular where is most of the (80828.438 ms) spent on
> the plan
> http://pastebin.com/d1e4bdea7 (reference to actual line
> number is appreciated)
>
>
>
> structure of a typical partition (abridged)
>
> Table "rfi_partitions.rfis_part_2009_01"
> Column | Type |
> Modifiers
> -----------------------+------------------------+---------------------------------------------------------------
> rfi_id | integer | not null
> default
> nextval('general.rfis_rfi_id_seq'::regclass)
> sender_uid | integer | not null
> receiver_uid | integer | not null
> subject | character varying(100) | not null
> message | text | not null
> inquiry_type | character varying(50) | default
> 'BUY'::character varying
> inquiry_source | character varying(30) | not null
> generated_date | integer | not null
> default
> general.current_date_id()
> Indexes:
> "rfis_part_2009_01_pkey" PRIMARY KEY, btree
> (rfi_id)
> "rfis_part_2009_01_generated_date" btree
> (generated_date)
> "rfis_part_2009_01_receiver_uid" btree
> (receiver_uid) CLUSTER
> "rfis_part_2009_01_sender_uid" btree
> (sender_uid)
> Check constraints:
> "rfis_part_2009_01_generated_date_check"
> CHECK (generated_date >=
> 3289 AND generated_date <= 3319)
> "rfis_part_2009_01_rfi_id_check" CHECK
> (rfi_id >= 12344252 AND
> rfi_id <= 12681399)
> Inherits: rfis
>
> regds
> rajesh kumar mallah.
>
> --
> Sent via pgsql-performance mailing list
> (pgsql-performance@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-performance
thanks for the hint,
now the peak hour is over and the same scan is taking 71 ms in place of 80000 ms
and the total query time is also acceptable. But it is surprising that
the scan was
taking so long consistently at that point of time. I shall test again
under similar
circumstance tomorrow.
Is it possible to enable block level statistics from the psql prompt
for a particular query
and see the results on the psql prompt ?
explain analyze SELECT count(*) from
rfi_partitions.rfis_part_2006_02 where generated_date >= 2251 and
receiver_uid=1320721 ;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=6.44..6.45 rows=1 width=0) (actual
time=71.513..71.513 rows=1 loops=1)
-> Index Scan using rfis_part_2006_02_generated_date on
rfis_part_2006_02 (cost=0.00..6.43 rows=1 width=0) (actual
time=71.508..71.508 rows=0 loops=1)
Index Cond: (generated_date >= 2251)
Filter: (receiver_uid = 1320721)
Total runtime: 71.553 ms
(5 rows)
hurray!
ANALYZING changed the plan
I was not expecting the plan to change because
the partition of 2006_02 is supposed to be
dormant. maybe the partition was never analyzed.
But still question remains, why the time taken was
in orders of magnitude higher in loaded condition.
tradein_clients=> explain SELECT count(*) from
rfi_partitions.rfis_part_2006_02 where generated_date >= 2251 and
receiver_uid=1320721 ;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------
Aggregate (cost=6.44..6.45 rows=1 width=0)
-> Index Scan using rfis_part_2006_02_generated_date on
rfis_part_2006_02 (cost=0.00..6.43 rows=1 width=0)
Index Cond: (generated_date >= 2251)
Filter: (receiver_uid = 1320721)
(4 rows)
tradein_clients=> ANALYZE rfi_partitions.rfis_part_2006_02;
ANALYZE
tradein_clients=> explain SELECT count(*) from
rfi_partitions.rfis_part_2006_02 where generated_date >= 2251 and
receiver_uid=1320721 ;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------
Aggregate (cost=8.78..8.79 rows=1 width=0)
-> Index Scan using rfis_part_2006_02_receiver_uid on
rfis_part_2006_02 (cost=0.00..8.77 rows=1 width=0)
Index Cond: (receiver_uid = 1320721)
Filter: (generated_date >= 2251)
(4 rows)
tradein_clients=> explain analyze SELECT count(*) from
rfi_partitions.rfis_part_2006_02 where generated_date >= 2251 and
receiver_uid=1320721 ;
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=8.78..8.79 rows=1 width=0) (actual time=0.045..0.045
rows=1 loops=1)
-> Index Scan using rfis_part_2006_02_receiver_uid on
rfis_part_2006_02 (cost=0.00..8.77 rows=1 width=0) (actual
time=0.042..0.042 rows=0 loops=1)
Index Cond: (receiver_uid = 1320721)
Filter: (generated_date >= 2251)
Total runtime: 0.082 ms
(5 rows)
tradein_clients=>
On Wed, Feb 11, 2009 at 6:07 PM, Rajesh Kumar Mallah
<mallah.rajesh@gmail.com> wrote:
> thanks for the hint,
>
> now the peak hour is over and the same scan is taking 71 ms in place of 80000 ms
> and the total query time is also acceptable. But it is surprising that
> the scan was
> taking so long consistently at that point of time. I shall test again
> under similar
> circumstance tomorrow.
>
> Is it possible to enable block level statistics from the psql prompt
> for a particular query
> and see the results on the psql prompt ?
>
> explain analyze SELECT count(*) from
> rfi_partitions.rfis_part_2006_02 where generated_date >= 2251 and
> receiver_uid=1320721 ;
>
> QUERY PLAN
>
------------------------------------------------------------------------------------------------------------------------------------------------------------
> Aggregate (cost=6.44..6.45 rows=1 width=0) (actual
> time=71.513..71.513 rows=1 loops=1)
> -> Index Scan using rfis_part_2006_02_generated_date on
> rfis_part_2006_02 (cost=0.00..6.43 rows=1 width=0) (actual
> time=71.508..71.508 rows=0 loops=1)
> Index Cond: (generated_date >= 2251)
> Filter: (receiver_uid = 1320721)
> Total runtime: 71.553 ms
> (5 rows)
>