pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedQuery execution time Vs Cost
3+ messages / 2 participants
[nested] [flat]
* Query execution time Vs Cost
@ 2019-09-13 11:08 Amarendra Konda <amar.vijaya@gmail.com>
0 siblings, 1 reply; 3+ messages in thread
From: Amarendra Konda @ 2019-09-13 11:08 UTC (permalink / raw)
To: pgsql-performance@lists.postgresql.org
Hi,
As part of one query tuning, it was observed that query execution time was
more even though cost was decreased.
*Initial Query :* Nested Loop Left Join (cost=159.88..*38530.02* rows=1
width=8) (actual time=0.387..*40.766* rows=300 loops=1)
*Changed Query :* Nested Loop Anti Join (cost=171.66..*5961.96* rows=1
width=8) (actual time=0.921..*110.862* rows=300 loops=1)
May i know the reason behind in increase in response time, even though cost
was reduced by 6.4 times.
Detailed execution plans can be found below along with the queries
*Initial Query*
=> explain(analyze,buffers,costs) SELECT ku.user_id
> FROM konotor_user ku
> LEFT JOIN agent_details ad
> ON ku.user_id = ad.user_id
> WHERE ku.app_id = '12132818272260'
> AND (ku.user_type = 1 OR ku.user_type = 2)
> AND (ad.deleted isnull OR ad.deleted = 0)
> AND ku.user_id NOT IN (
> SELECT gu.user_id
> FROM group_user gu
> INNER JOIN groups
> ON gu.group_id = groups.group_id
> AND app_id = ku.app_id
> WHERE gu.user_id = ku.user_id
> AND groups.app_id = ku.app_id
> AND groups.deleted = false);
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=159.88..38530.02 rows=1 width=8) (actual
time=0.387..40.766 rows=300 loops=1)
Filter: ((ad.deleted IS NULL) OR (ad.deleted = 0))
Buffers: shared hit=52138
-> Bitmap Heap Scan on konotor_user ku (cost=159.73..38383.64 rows=712
width=8) (actual time=0.383..40.221 rows=300 loops=1)
Recheck Cond: (((app_id = '12132818272260'::bigint) AND (user_type
= 1)) OR ((app_id = '12132818272260'::bigint) AND (user_type = 2)))
Filter: (NOT (SubPlan 1))
Rows Removed by Filter: 485
Heap Blocks: exact=729
Buffers: shared hit=51838
-> BitmapOr (cost=159.73..159.73 rows=1425 width=0) (actual
time=0.112..0.112 rows=0 loops=1)
Buffers: shared hit=11
-> Bitmap Index Scan on konotor_user_app_id_user_type_idx
(cost=0.00..88.42 rows=786 width=0) (actual time=0.009..0.009 rows=1
loops=1)
Index Cond: ((app_id = '12132818272260'::bigint) AND
(user_type = 1))
Buffers: shared hit=4
-> Bitmap Index Scan on konotor_user_app_id_user_type_idx
(cost=0.00..70.95 rows=639 width=0) (actual time=0.101..0.101 rows=784
loops=1)
Index Cond: ((app_id = '12132818272260'::bigint) AND
(user_type = 2))
Buffers: shared hit=7
SubPlan 1
-> Nested Loop (cost=0.57..45.28 rows=1 width=8) (actual
time=0.049..0.049 rows=1 loops=785)
Buffers: shared hit=51098
-> Index Scan using groups_app_id_group_id_idx on groups
(cost=0.28..20.33 rows=3 width=8) (actual time=0.002..0.014 rows=20
loops=785)
Index Cond: (app_id = ku.app_id)
Filter: (NOT deleted)
Rows Removed by Filter: 2
Buffers: shared hit=18888
-> Index Only Scan using uk_groupid_userid on group_user
gu (cost=0.29..8.30 rows=1 width=16) (actual time=0.001..0.001 rows=0
loops=15832)
Index Cond: ((group_id = groups.group_id) AND
(user_id = ku.user_id))
Heap Fetches: 455
Buffers: shared hit=32210
-> Index Scan using agent_details_user_id_idx on agent_details ad
(cost=0.15..0.19 rows=1 width=10) (actual time=0.001..0.001 rows=0
loops=300)
Index Cond: (ku.user_id = user_id)
Buffers: shared hit=300
Planning time: 0.493 ms
Execution time: 40.901 ms
*Changed Query *
=> explain(analyze,buffers,costs) SELECT ku.user_id FROM konotor_user ku
> LEFT OUTER JOIN agent_details ad ON ku.user_id = ad.user_id LEFT OUTER JOIN
> (SELECT gu.user_id
> FROM group_user gu INNER JOIN groups ON
> gu.group_id = groups.group_id WHERE app_id='12132818272260' AND
> groups.deleted = false)t ON t.user_id= ku.user_id
> WHERE ku.app_id = '12132818272260'
> AND (ku.user_type = 1 OR ku.user_type = 2) AND
> (ad.deleted isnull OR ad.deleted = 0) AND t.user_id is NULL;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Anti Join (cost=171.66..5961.96 rows=1 width=8) (actual
time=0.921..110.862 rows=300 loops=1)
Buffers: shared hit=47730
-> Hash Left Join (cost=171.10..5730.86 rows=1 width=8) (actual
time=0.435..2.201 rows=785 loops=1)
Hash Cond: (ku.user_id = ad.user_id)
Filter: ((ad.deleted IS NULL) OR (ad.deleted = 0))
Buffers: shared hit=743
-> Bitmap Heap Scan on konotor_user ku (cost=160.09..5714.50
rows=1424 width=8) (actual time=0.208..1.327 rows=785 loops=1)
Recheck Cond: (((app_id = '12132818272260'::bigint) AND
(user_type = 1)) OR ((app_id = '12132818272260'::bigint) AND (user_type =
2)))
Heap Blocks: exact=729
Buffers: shared hit=740
-> BitmapOr (cost=160.09..160.09 rows=1425 width=0)
(actual time=0.116..0.116 rows=0 loops=1)
Buffers: shared hit=11
-> Bitmap Index Scan on
konotor_user_app_id_user_type_idx (cost=0.00..88.42 rows=786 width=0)
(actual time=0.010..0.010 rows=1 loops=1)
Index Cond: ((app_id = '12132818272260'::bigint)
AND (user_type = 1))
Buffers: shared hit=4
-> Bitmap Index Scan on
konotor_user_app_id_user_type_idx (cost=0.00..70.95 rows=639 width=0)
(actual time=0.105..0.105 rows=784 loops=1)
Index Cond: ((app_id = '12132818272260'::bigint)
AND (user_type = 2))
Buffers: shared hit=7
-> Hash (cost=6.56..6.56 rows=356 width=10) (actual
time=0.220..0.220 rows=356 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 23kB
Buffers: shared hit=3
-> Seq Scan on agent_details ad (cost=0.00..6.56 rows=356
width=10) (actual time=0.003..0.101 rows=356 loops=1)
Buffers: shared hit=3
-> Nested Loop (cost=0.57..115.82 rows=1 width=8) (actual
time=0.138..0.138 rows=1 loops=785)
Buffers: shared hit=46987
-> Index Only Scan using uk_groupid_userid on group_user gu
(cost=0.29..115.12 rows=2 width=16) (actual time=0.135..0.135 rows=1
loops=785)
Index Cond: (user_id = ku.user_id)
Heap Fetches: 456
Buffers: shared hit=45529
-> Index Scan using groups_pkey on groups (cost=0.28..0.34
rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=486)
Index Cond: (group_id = gu.group_id)
Filter: ((NOT deleted) AND (app_id =
'12132818272260'::bigint))
Rows Removed by Filter: 0
Buffers: shared hit=1458
Planning time: 0.534 ms
Execution time: 110.999 ms
(36 rows)
*PostgreSQL version : PostgreSQL 9.6.2 on x86_64-pc-linux-gnu, compiled by
gcc (GCC) 4.8.3 20140911 (Red Hat 4.8.3-9), 64-bit*
Thanks in advance for your valuable time and inputs.
Regards, Amarendra
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Query execution time Vs Cost
@ 2019-09-13 23:06 Justin Pryzby <pryzby@telsasoft.com>
parent: Amarendra Konda <amar.vijaya@gmail.com>
0 siblings, 1 reply; 3+ messages in thread
From: Justin Pryzby @ 2019-09-13 23:06 UTC (permalink / raw)
To: Amarendra Konda <amar.vijaya@gmail.com>; +Cc: pgsql-performance@lists.postgresql.org
On Fri, Sep 13, 2019 at 04:38:50PM +0530, Amarendra Konda wrote:
> As part of one query tuning, it was observed that query execution time was
> more even though cost was decreased.
..
> May i know the reason behind in increase in response time, even though cost
> was reduced by 6.4 times.
The "cost" is postgres model for how expensive a plan will be, based on table
statistics, and parameters like seq/rand_page_cost, etc. It's an imperfect
model and not exact.
> *Initial Query*
>
> => explain(analyze,buffers,costs) SELECT ku.user_id
> > FROM konotor_user ku
> > LEFT JOIN agent_details ad
> > ON ku.user_id = ad.user_id
> > WHERE ku.app_id = '12132818272260'
> > AND (ku.user_type = 1 OR ku.user_type = 2)
> > AND (ad.deleted isnull OR ad.deleted = 0)
> > AND ku.user_id NOT IN (
> > SELECT gu.user_id
> > FROM group_user gu
> > INNER JOIN groups
> > ON gu.group_id = groups.group_id
> > AND app_id = ku.app_id
> > WHERE gu.user_id = ku.user_id
> > AND groups.app_id = ku.app_id
> > AND groups.deleted = false);
It seems to me the major difference is in group_user JOIN groups.
In the fast query, it did
> -> Index Only Scan using uk_groupid_userid on group_user gu (cost=0.29..8.30 rows=1 width=16) (actual time=0.001..0.001 rows=0 loops=15832)
> Index Cond: ((group_id = groups.group_id) AND (user_id = ku.user_id))
> Heap Fetches: 455
> Buffers: shared hit=32210
=> 15832*0.001sec = 15ms
In the slow query it did:
> -> Index Only Scan using uk_groupid_userid on group_user gu (cost=0.29..115.12 rows=2 width=16) (actual time=0.135..0.135 rows=1 loops=785)
> Index Cond: (user_id = ku.user_id)
> Heap Fetches: 456
> Buffers: shared hit=45529
=> 785*0.115sec = 90ms
It scanned using non-leading columns of index, so it took 6x longer even though
it did 20x fewer loops. Also it did 456 heap fetches (which were probably
nonsequential). Vacuuming the table will probably help; if so, you should
consider setting parameter to encourage more frequent autovacuums:
| ALTER TABLE group_user SET (AUTOVACUUM_VACUUM_SCALE_FACTOR=0.005);
Justin
^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Query execution time Vs Cost
@ 2019-09-14 04:24 Amarendra Konda <amar.vijaya@gmail.com>
parent: Justin Pryzby <pryzby@telsasoft.com>
0 siblings, 0 replies; 3+ messages in thread
From: Amarendra Konda @ 2019-09-14 04:24 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: pgsql-performance@lists.postgresql.org
Hi Justin,
Thanks a lot for the detailed analysis and explanation for slowness that
was seen. Pointed noted related to the vacuum tuning option.
Regards, Amarendra
On Sat, Sep 14, 2019 at 4:36 AM Justin Pryzby <pryzby@telsasoft.com> wrote:
> On Fri, Sep 13, 2019 at 04:38:50PM +0530, Amarendra Konda wrote:
> > As part of one query tuning, it was observed that query execution time
> was
> > more even though cost was decreased.
>
> ..
>
> > May i know the reason behind in increase in response time, even though
> cost
> > was reduced by 6.4 times.
>
> The "cost" is postgres model for how expensive a plan will be, based on
> table
> statistics, and parameters like seq/rand_page_cost, etc. It's an imperfect
> model and not exact.
>
> > *Initial Query*
> >
> > => explain(analyze,buffers,costs) SELECT ku.user_id
> > > FROM konotor_user ku
> > > LEFT JOIN agent_details ad
> > > ON ku.user_id = ad.user_id
> > > WHERE ku.app_id = '12132818272260'
> > > AND (ku.user_type = 1 OR ku.user_type = 2)
> > > AND (ad.deleted isnull OR ad.deleted = 0)
> > > AND ku.user_id NOT IN (
> > > SELECT gu.user_id
> > > FROM group_user gu
> > > INNER JOIN groups
> > > ON gu.group_id = groups.group_id
> > > AND app_id = ku.app_id
> > > WHERE gu.user_id = ku.user_id
> > > AND groups.app_id = ku.app_id
> > > AND groups.deleted = false);
>
> It seems to me the major difference is in group_user JOIN groups.
>
> In the fast query, it did
> > -> Index Only Scan using uk_groupid_userid on
> group_user gu (cost=0.29..8.30 rows=1 width=16) (actual time=0.001..0.001
> rows=0 loops=15832)
> > Index Cond: ((group_id = groups.group_id) AND
> (user_id = ku.user_id))
> > Heap Fetches: 455
> > Buffers: shared hit=32210
>
> => 15832*0.001sec = 15ms
>
> In the slow query it did:
> > -> Index Only Scan using uk_groupid_userid on group_user gu
> (cost=0.29..115.12 rows=2 width=16) (actual time=0.135..0.135 rows=1
> loops=785)
> > Index Cond: (user_id = ku.user_id)
> > Heap Fetches: 456
> > Buffers: shared hit=45529
>
> => 785*0.115sec = 90ms
>
> It scanned using non-leading columns of index, so it took 6x longer even
> though
> it did 20x fewer loops. Also it did 456 heap fetches (which were probably
> nonsequential). Vacuuming the table will probably help; if so, you should
> consider setting parameter to encourage more frequent autovacuums:
> | ALTER TABLE group_user SET (AUTOVACUUM_VACUUM_SCALE_FACTOR=0.005);
>
> Justin
>
^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2019-09-14 04:24 UTC | newest]
Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2019-09-13 11:08 Query execution time Vs Cost Amarendra Konda <amar.vijaya@gmail.com>
2019-09-13 23:06 ` Justin Pryzby <pryzby@telsasoft.com>
2019-09-14 04:24 ` Amarendra Konda <amar.vijaya@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox