OK, I've got a query that's running slow the first time, then fast.
But I can't see where the time is really being spend on the first run.
 Query and plan attached to preserve formatting.

The index scan and nested loop that feed the next layer up nested loop
both show very short run times.  Yet the nested loop they feed to
takes 30 seconds to run.  If I run the query a second time, everything
looks the same but the second nested loop now runs in well under a
second.

I can't figure out where my time's going to.
=# explain analyze SELECT u.*, to_char(u.registration_date, 'Month FMDD, YYYY') 
AS f_registration_date FROM  users u  INNER JOIN (org_relationships_join j1 
INNER JOIN org_relationships_join j2 ON j1.relid = j2.relid) ON u.orgid = 
j2.orgid  WHERE j1.orgid = 142550 AND u.deleted = 0 AND u.type_id < 10  AND ( 
lower(u.lname) LIKE lower('boat%') OR lower(u.fname) LIKE lower('boat%') OR 
lower(u.username) LIKE lower('boat%') OR lower(u.option1) LIKE lower('boat%') 
OR lower(u.email) LIKE lower('%boat%') OR lower(u.external_id) = lower('boat')  
) ORDER BY lower(u.lname), lower(u.fname) ;

QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=2625.26..2625.51 rows=99 width=271) (actual 
time=30123.181..30123.183 rows=4 loops=1)
   Sort Key: (lower((u.lname)::text)), (lower((u.fname)::text))
   Sort Method:  quicksort  Memory: 26kB
   ->  Nested Loop  (cost=0.00..2621.98 rows=99 width=271) (actual 
time=26919.298..30123.065 rows=4 loops=1)
         ->  Nested Loop  (cost=0.00..29.36 rows=20 width=4) (actual 
time=0.099..0.383 rows=35 loops=1)
               ->  Index Scan using org_relationships_orgid_idx on 
org_relationships_join j1  (cost=0.00..8.27 rows=1 width=4) (actual 
time=0.048..0.051 rows=1 loops=1)
                     Index Cond: (orgid = 142550)
               ->  Index Scan using org_relationships_relid_idx on 
org_relationships_join j2  (cost=0.00..21.00 rows=7 width=8) (actual 
time=0.046..0.222 rows=35 loops=1)
                     Index Cond: (j2.relid = j1.relid)
         ->  Index Scan using users_orgid_idx on users u  (cost=0.00..129.52 
rows=5 width=271) (actual time=843.825..860.638 rows=0 loops=35)
               Index Cond: (u.orgid = j2.orgid)
               Filter: ((u.type_id < 10) AND (u.deleted = 0) AND 
((lower((u.lname)::text) ~~ 'boat%'::text) OR (lower((u.fname)::text) ~~ 
'boat%'::text) OR (lower((u.username)::text) ~~ 'boat%'::text) OR 
(lower(u.option1) ~~ 'boat%'::text) OR (lower((u.email)::text) ~~ 
'%boat%'::text) OR (lower(u.external_id) = 'boat'::text)))
 Total runtime: 30123.405 ms


Second run:
 Sort  (cost=2625.30..2625.55 rows=99 width=271) (actual time=116.011..116.012 
rows=4 loops=1)
   Sort Key: (lower((u.lname)::text)), (lower((u.fname)::text))
   Sort Method:  quicksort  Memory: 26kB
   ->  Nested Loop  (cost=0.00..2622.02 rows=99 width=271) (actual 
time=79.531..115.958 rows=4 loops=1)
         ->  Nested Loop  (cost=0.00..29.36 rows=20 width=4) (actual 
time=0.036..0.126 rows=35 loops=1)
               ->  Index Scan using org_relationships_orgid_idx on 
org_relationships_join j1  (cost=0.00..8.27 rows=1 width=4) (actual 
time=0.016..0.018 rows=1 loops=1)
                     Index Cond: (orgid = 142550)
               ->  Index Scan using org_relationships_relid_idx on 
org_relationships_join j2  (cost=0.00..21.00 rows=7 width=8) (actual 
time=0.014..0.068 rows=35 loops=1)
                     Index Cond: (j2.relid = j1.relid)
         ->  Index Scan using users_orgid_idx on users u  (cost=0.00..129.52 
rows=5 width=271) (actual time=3.126..3.305 rows=0 loops=35)
               Index Cond: (u.orgid = j2.orgid)
               Filter: ((u.type_id < 10) AND (u.deleted = 0) AND 
((lower((u.lname)::text) ~~ 'boat%'::text) OR (lower((u.fname)::text) ~~ 
'boat%'::text) OR (lower((u.username)::text) ~~ 'boat%'::text) OR 
(lower(u.option1) ~~ 'boat%'::text) OR (lower((u.email)::text) ~~ 
'%boat%'::text) OR (lower(u.external_id) = 'boat'::text)))
 Total runtime: 116.214 ms

-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Reply via email to