0

I am struggling with a query running for 30 seconds on one of my db hosts. Same query ( same configuration for db in postgresql.conf ) runs in 3 seconds with a different execution plan. Yes the amount of data is a little bit different. but not as huge as explaining the difference.

I checked and tried different values for work parameters , but reached not the result I am looking for . I vacuumed analyzed all tables in the select .. but nothing .

Any idea would be great to help me solve this .

  1. query :
select count(*)  from products itm, propertymaps pmp 
 where pmp.instanceid = itm.instPropertyMapId   
 and itm.validUntil >= '2023-08-08 00:00:00'  
 and itm.validFrom <= '2023-08-08 00:00:00'   
 and itm.productGroupId in (            select childId              
 from inheritances            
  where parentid in ('218900559', '218900537', '218900603', '218900581'))   
  and itm.ownerid in ('9377779201619')   
  and cast(pmp.properties->'props'->>'4049111000000/PUBLISHING_PriceAvailableState,,,' as boolean)   
  and EXISTS (select 'x' from tags tg where tg.objinstanceid = itm.instanceid and tg.category = 'APPROVAL.POOL1');
  1. SLOW Execution PLAN
Finalize Aggregate  (cost=1602884.65..1602884.66 rows=1 width=8) (actual time=34882.280..34887.119 rows=1 loops=1)\
   ->  Gather  (cost=1602884.54..1602884.65 rows=1 width=8) (actual time=34881.099..34887.111 rows=2 loops=1)\
         Workers Planned: 1\
         Workers Launched: 1\
         ->  Partial Aggregate  (cost=1601884.54..1601884.55 rows=1 width=8) (actual time=34806.871..34806.876 rows=1 loops=2)\
               ->  Nested Loop Semi Join  (cost=41813.92..1601510.41 rows=149650 width=0) (actual time=368.775..34796.374 rows=41900 loops=2)\
                     ->  Nested Loop  (cost=41813.36..1456210.51 rows=149650 width=8) (actual time=368.024..34079.434 rows=41900 loops=2)\
                           ->  Hash Join  (cost=41812.79..665715.22 rows=310854 width=16) (actual time=365.470..12493.936 rows=114248 loops=2)\
                                 Hash Cond: (itm.productgroupid = inheritances.childid)\
                                 ->  Parallel Bitmap Heap Scan on products itm  (cost=41803.16..661023.35 rows=466281 width=24) (actual time=365.111..12372.259 rows=438874 loops=2)\
                                       Recheck Cond: ((ownerid = '9377779201619'::bigint) AND (validfrom <= '2023-08-08 00:00:00'::timestamp without time zone) AND (validuntil >= '2023-08-08 00:00:00'::timestamp without time zone))\
                                       Heap Blocks: exact=76675
                                       ->  Bitmap Index Scan on products_idx_date  (cost=0.00..41604.99 rows=792677 width=0) (actual time=356.026..356.027 rows=877771 loops=1)\
                                             Index Cond: ((ownerid = '9377779201619'::bigint) AND (validfrom <= '2023-08-08 00:00:00'::timestamp without time zone) AND (validuntil >= '2023-08-08 00:00:00'::timestamp without time zone))\
                                 ->  Hash  (cost=9.58..9.58 rows=4 width=8) (actual time=0.073..0.075 rows=4 loops=2)\
                                       Buckets: 1024  Batches: 1  Memory Usage: 9kB\
                                       ->  HashAggregate  (cost=9.54..9.58 rows=4 width=8) (actual time=0.068..0.070 rows=4 loops=2)\
                                             Group Key: inheritances.childid\
                                             ->  Index Scan using inh_p on inheritances  (cost=0.28..9.53 rows=4 width=8) (actual time=0.054..0.063 rows=4 loops=2)\
                                                   Index Cond: (parentid = ANY ('{218900559,218900537,218900603,218900581}'::bigint[]))\
                           ->  Index Scan using pmp_pk on propertymaps pmp  (cost=0.57..2.54 rows=1 width=8) (actual time=0.188..0.188 rows=0 loops=228497)\
                                 Index Cond: (instanceid = itm.instpropertymapid)\
                                 Filter: (((properties -> 'props'::text) ->> '4049111000000/PUBLISHING_PriceAvailableState,,,'::text))::boolean
                                 Rows Removed by Filter: 1\
                     ->  Index Only Scan using tags_idx1 on tags tg  (cost=0.57..1.56 rows=4 width=8) (actual time=0.016..0.016 rows=1 loops=83800)\
                           Index Cond: ((category = 'APPROVAL.POOL1'::text) AND (objinstanceid = itm.instanceid))\
                           Heap Fetches: 66\
 Planning Time: 4.554 ms\
 Execution Time: 34911.589 ms\
(29 rows)
  1. FAST ONE prodpgdb18=# explain analyze
 select count(*)  from products 
 itm, propertymaps pmp 
 where pmp.instanceid = itm.instPropertyMapId   
 and itm.validUntil >= '2023-08-08 00:00:00'  
 and itm.validFrom <= '2023-08-08 00:00:00'   
 and itm.productGroupId in (            select childId              
 from inheritances            
  where parentid in ('218900559', '218900537', '218900603', '218900581'))   
  and itm.ownerid in ('9377779201619')   
  and cast(pmp.properties->'props'->>'4049111000000/PUBLISHING_PriceAvailableState,,,' as boolean)   
  and EXISTS (select 'x' from tags tg where tg.objinstanceid = itm.instanceid and tg.category = 'APPROVAL.POOL1');

QUERY PLAN

 Finalize Aggregate  (cost=141867.29..141867.30 rows=1 width=8) (actual time=10.458..12.857 rows=1 loops=1)\
   ->  Gather  (cost=141866.87..141867.28 rows=4 width=8) (actual time=1.205..12.842 rows=4 loops=1)\
         Workers Planned: 4\
         Workers Launched: 3\
         ->  Partial Aggregate  (cost=140866.87..140866.88 rows=1 width=8) (actual time=0.093..0.097 rows=1 loops=4)\
               ->  Nested Loop Semi Join  (cost=2138.98..140866.52 rows=141 width=0) (actual time=0.089..0.093 rows=0 loops=4)\
                     ->  Nested Loop  (cost=2138.29..140694.31 rows=141 width=8) (actual time=0.089..0.093 rows=0 loops=4)\
                           ->  Hash Join  (cost=2137.72..138254.70 rows=284 width=16) (actual time=0.088..0.092 rows=0 loops=4)\
                                 Hash Cond: (itm.productgroupid = inheritances.childid)\
                                 ->  Parallel Bitmap Heap Scan on products itm  (cost=2112.90..138221.37 rows=2046 width=24) (never executed)\
                                       Recheck Cond: (ownerid = '9377779201619'::bigint)\
                                       Filter: ((validuntil >= '2023-08-08 00:00:00'::timestamp without time zone) AND (validfrom <= '2023-08-08 00:00:00'::timestamp without time zone))\
                                       ->  Bitmap Index Scan on itm_ownerid_idx  (cost=0.00..2110.86 rows=36038 width=0) (never executed)
                                             Index Cond: (ownerid = '9377779201619'::bigint)\
                                 ->  Hash  (cost=24.77..24.77 rows=4 width=8) (actual time=0.036..0.037 rows=0 loops=4)\
                                       Buckets: 1024  Batches: 1  Memory Usage: 8kB\
                                       ->  HashAggregate  (cost=24.73..24.77 rows=4 width=8) (actual time=0.035..0.036 rows=0 loops=4)\
                                             Group Key: inheritances.childid\
                                             ->  Bitmap Heap Scan on inheritances  (cost=17.14..24.72 rows=4 width=8) (actual time=0.034..0.035 rows=0 loops=4)\
                                                   Recheck Cond: (parentid = ANY ('{218900559,218900537,218900603,218900581}'::bigint[]))\
                                                   ->  Bitmap Index Scan on inh_p  (cost=0.00..17.14 rows=4 width=0) (actual time=0.029..0.029 rows=0 loops=4)\
                                                         Index Cond: (parentid = ANY ('{218900559,218900537,218900603,218900581}'::bigint[]))\
                           ->  Index Scan using pmp_pk on propertymaps pmp  (cost=0.57..8.59 rows=1 width=8) (never executed)\
                                 Index Cond: (instanceid = itm.instpropertymapid)\
                                 Filter: (((properties -> 'props'::text) ->> '4049111000000/PUBLISHING_PriceAvailableState,,,'::text))::boolean\
                     ->  Index Only Scan using tags_idx1 on tags tg  (cost=0.70..5.01 rows=16 width=8) (never executed)\
                           Index Cond: ((category = 'APPROVAL.POOL1'::text) AND (objinstanceid = itm.instanceid))\
                           Heap Fetches: 0\
 Planning Time: 2.321 ms\
 Execution Time: 13.062 ms\
(30 rows)
1
  • "Yes the amount of data is a little bit different" A little bit? One processes 41900 rows, one processes zero.
    – jjanes
    Aug 10, 2023 at 0:11

1 Answer 1

0

Usually the first thing to try is to make sure the statistics are up to date on all of the hosts.

analyze verbose propertymaps;
analyze verbose products;

I assume the schema and indexes are identical already.

Another thing you can try is pg_repack on the tables to remove bloat on all of the hosts.

If nothing else works you can disable nested_loops (when you run the query).

set enable_nestloop = 0;
1
  • unfortunately , verbose did not solve the issue same runtime Planning Time: 6.108 ms Execution Time: 32834.166 ms (29 rows) and set enable_nestloop = 0; .. no even more worse :((
    – Nicole
    Aug 9, 2023 at 14:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.