Query execution time Vs Cost

[Amarendra Konda <amar.vijaya@xxxxxxxxx>]

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