Query performing very bad and sometimes good - Mailing list pgsql-performance

From Andreas Joseph Krogh
Subject Query performing very bad and sometimes good
Date
Msg-id VisenaEmail.24.fd3487f9d1329566.147a8117731@tc7-on
Whole thread Raw
Responses Re: Query performing very bad and sometimes good
Re: Query performing very bad and sometimes good
List pgsql-performance
Hi all.
 
Running version:
on=> select version();
                                                  version
------------------------------------------------------------------------------------------------------------
 PostgreSQL 9.3.2 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit
 
 
I have this query.
 
prepare list_un_done_in_folder_q AS
SELECT em.entity_id, substr(em.plain_text_content, 1, 101) as plain_text_content, del.entity_id as delivery_id, del.subject,
                     coalesce(prop.is_seen, false) AS is_seen,
                                                coalesce(prop.is_done, false) AS is_done,
    del.received_timestamp, del.sent_timestamp, ef.name as from_name, ef.address as from_address
    , ARRAY(select a.name from origo_email_address a inner join origo_email_address_owner o ON o.address_id = a.entity_id AND o.recipient_type = 'TO' AND o.message_id = em.entity_id ORDER BY o.address_index ASC) as recipient_to_name
    , ARRAY(select a.address from origo_email_address a inner join origo_email_address_owner o ON o.address_id = a.entity_id AND o.recipient_type = 'TO' AND o.message_id = em.entity_id ORDER BY o.address_index ASC) as recipient_to_address
    , prop.followup_id, prop.is_forwarded as is_forwarded, prop.is_replied as is_replied, fm.folder_id
    , (SELECT
                                                person_fav.priority
       FROM origo_favourite_owner person_fav
       WHERE person_fav.favourite_for = $1
             AND person_fav.favourite_item = pers.entity_id)
    AS person_favourite_priority
    , (select company_fav.priority FROM origo_favourite_owner company_fav WHERE company_fav.favourite_for = $2
                                                                                AND company_fav.favourite_item = comp.entity_id)
    AS company_favourite_priority
    , pers.entity_id as from_person_entity_id, pers.id as from_person_id, pers.onp_user_id, pers.firstname as from_firstname, pers.lastname as from_lastname
    , comp.entity_id as from_company_entity_id, comp.companyname as from_company_name
    , em.attachment_size
FROM origo_email_delivery del JOIN origo_email_message em ON (del.message_id = em.entity_id)
    LEFT OUTER JOIN onp_crm_person pers ON (em.from_entity_id = pers.entity_id)
    LEFT OUTER JOIN onp_crm_relation comp ON (comp.entity_id = pers.relation_id)
    JOIN origo_email_message_property prop ON (em.entity_id = prop.message_id AND prop.owner_id = $3)
    LEFT OUTER JOIN origo_email_address ef ON em.from_id = ef.entity_id
    LEFT OUTER JOIN origo_email_folder_message fm ON fm.delivery_id = del.entity_id
WHERE 1 = 1
      AND prop.is_done = FALSE
      AND fm.folder_id = $4
ORDER BY  del.received_timestamp DESC LIMIT $5 OFFSET $6;
 
Which sometimes performs really bad, although all indexes are being used.
 
Here is the explain plan:
 
on=> explain analyze execute list_un_done_in_folder_q (3,3,3,44961, 101, 0);
                                                                                                             QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=2.53..52101.30 rows=101 width=641) (actual time=0.343..311765.063 rows=75 loops=1)
   ->  Nested Loop Left Join  (cost=2.53..1365402.92 rows=2647 width=641) (actual time=0.342..311765.012 rows=75 loops=1)
         ->  Nested Loop Left Join  (cost=2.10..1248967.97 rows=2647 width=607) (actual time=0.202..311215.044 rows=75 loops=1)
               ->  Nested Loop Left Join  (cost=1.83..1248018.82 rows=2647 width=592) (actual time=0.201..311214.888 rows=75 loops=1)
                     ->  Nested Loop  (cost=1.55..1247217.37 rows=2647 width=565) (actual time=0.199..311214.695 rows=75 loops=1)
                           ->  Nested Loop  (cost=1.13..1240583.78 rows=2647 width=126) (actual time=0.194..311213.727 rows=75 loops=1)
                                 ->  Nested Loop  (cost=0.71..1230153.64 rows=20567 width=118) (actual time=0.029..311153.648 rows=12866 loops=1)
                                       ->  Index Scan Backward using origo_email_delivery_received_idx on origo_email_delivery del  (cost=0.42..1102717.48 rows=354038 width=98) (actual time=0.017..309196.670 rows=354296 loops=1)
                                       ->  Index Scan using origo_email_prop_owner_message_not_done_idx on origo_email_message_property prop  (cost=0.29..0.35 rows=1 width=20) (actual time=0.004..0.004 rows=0 loops=354296)
                                             Index Cond: ((owner_id = 3::bigint) AND (message_id = del.message_id))
                                 ->  Index Only Scan using origo_email_folder_message_delivery_id_folder_id_key on origo_email_folder_message fm  (cost=0.42..0.50 rows=1 width=16) (actual time=0.004..0.004 rows=0 loops=12866)
                                       Index Cond: ((delivery_id = del.entity_id) AND (folder_id = 44961::bigint))
                                       Heap Fetches: 75
                           ->  Index Scan using origo_email_message_pkey on origo_email_message em  (cost=0.42..2.50 rows=1 width=455) (actual time=0.010..0.011 rows=1 loops=75)
                                 Index Cond: (entity_id = del.message_id)
                     ->  Index Scan using origo_person_entity_id_idx on onp_crm_person pers  (cost=0.28..0.29 rows=1 width=35) (actual time=0.001..0.001 rows=0 loops=75)
                           Index Cond: (em.from_entity_id = entity_id)
               ->  Index Scan using onp_crm_relation_pkey on onp_crm_relation comp  (cost=0.27..0.35 rows=1 width=19) (actual time=0.001..0.001 rows=0 loops=75)
                     Index Cond: (entity_id = pers.relation_id)
         ->  Index Scan using origo_email_address_pkey on origo_email_address ef  (cost=0.43..0.68 rows=1 width=50) (actual time=3.165..3.166 rows=1 loops=75)
               Index Cond: (em.from_id = entity_id)
         SubPlan 1
           ->  Nested Loop  (cost=0.85..16.90 rows=1 width=24) (actual time=1.880..1.882 rows=1 loops=75)
                 ->  Index Scan using origo_email_address_owner_message_id_recipient_type_address_key on origo_email_address_owner o  (cost=0.42..8.45 rows=1 width=12) (actual time=1.759..1.759 rows=1 loops=75)
                       Index Cond: ((message_id = em.entity_id) AND ((recipient_type)::text = 'TO'::text))
                 ->  Index Scan using origo_email_address_pkey on origo_email_address a  (cost=0.43..8.45 rows=1 width=28) (actual time=0.095..0.095 rows=1 loops=93)
                       Index Cond: (entity_id = o.address_id)
         SubPlan 2
           ->  Nested Loop  (cost=0.85..16.90 rows=1 width=26) (actual time=0.009..0.010 rows=1 loops=75)
                 ->  Index Scan using origo_email_address_owner_message_id_recipient_type_address_key on origo_email_address_owner o_1  (cost=0.42..8.45 rows=1 width=12) (actual time=0.005..0.006 rows=1 loops=75)
                       Index Cond: ((message_id = em.entity_id) AND ((recipient_type)::text = 'TO'::text))
                 ->  Index Scan using origo_email_address_pkey on origo_email_address a_1  (cost=0.43..8.45 rows=1 width=30) (actual time=0.002..0.002 rows=1 loops=93)
                       Index Cond: (entity_id = o_1.address_id)
         SubPlan 3
           ->  Seq Scan on origo_favourite_owner person_fav  (cost=0.00..4.75 rows=1 width=4) (actual time=0.024..0.024 rows=0 loops=75)
                 Filter: ((favourite_for = 3::bigint) AND (favourite_item = pers.entity_id))
                 Rows Removed by Filter: 183
         SubPlan 4
           ->  Seq Scan on origo_favourite_owner company_fav  (cost=0.00..4.75 rows=1 width=4) (actual time=0.021..0.021 rows=0 loops=75)
                 Filter: ((favourite_for = 3::bigint) AND (favourite_item = comp.entity_id))
                 Rows Removed by Filter: 183
 Total runtime: 311765.351 ms
(42 rows)
 
Some-times it performs much better (but still not good):
 
on=> explain analyze execute list_un_done_in_folder_q (3,3,3,44961, 101, 0);
                                                                                                            QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=2.53..52101.45 rows=101 width=641) (actual time=0.276..3480.876 rows=75 loops=1)
   ->  Nested Loop Left Join  (cost=2.53..1365406.92 rows=2647 width=641) (actual time=0.276..3480.846 rows=75 loops=1)
         ->  Nested Loop Left Join  (cost=2.10..1248971.97 rows=2647 width=607) (actual time=0.158..3461.045 rows=75 loops=1)
               ->  Nested Loop Left Join  (cost=1.83..1248022.82 rows=2647 width=592) (actual time=0.156..3460.955 rows=75 loops=1)
                     ->  Nested Loop  (cost=1.55..1247221.37 rows=2647 width=565) (actual time=0.155..3449.744 rows=75 loops=1)
                           ->  Nested Loop  (cost=1.13..1240587.78 rows=2647 width=126) (actual time=0.148..3449.134 rows=75 loops=1)
                                 ->  Nested Loop  (cost=0.71..1230157.64 rows=20567 width=118) (actual time=0.034..3407.201 rows=12870 loops=1)
                                       ->  Index Scan Backward using origo_email_delivery_received_idx on origo_email_delivery del  (cost=0.42..1102717.48 rows=354038 width=98) (actual time=0.019..2431.773 rows=354300 loops=1)
                                       ->  Index Scan using origo_email_prop_owner_message_not_done_idx on origo_email_message_property prop  (cost=0.29..0.35 rows=1 width=20) (actual time=0.002..0.002 rows=0 loops=354300)
                                             Index Cond: ((owner_id = 3::bigint) AND (message_id = del.message_id))
                                 ->  Index Only Scan using origo_email_folder_message_delivery_id_folder_id_key on origo_email_folder_message fm  (cost=0.42..0.50 rows=1 width=16) (actual time=0.003..0.003 rows=0 loops=12870)
                                       Index Cond: ((delivery_id = del.entity_id) AND (folder_id = 44961::bigint))
                                       Heap Fetches: 75
                           ->  Index Scan using origo_email_message_pkey on origo_email_message em  (cost=0.42..2.50 rows=1 width=455) (actual time=0.007..0.007 rows=1 loops=75)
                                 Index Cond: (entity_id = del.message_id)
                     ->  Index Scan using origo_person_entity_id_idx on onp_crm_person pers  (cost=0.28..0.29 rows=1 width=35) (actual time=0.000..0.000 rows=0 loops=75)
                           Index Cond: (em.from_entity_id = entity_id)
               ->  Index Scan using onp_crm_relation_pkey on onp_crm_relation comp  (cost=0.27..0.35 rows=1 width=19) (actual time=0.000..0.000 rows=0 loops=75)
                     Index Cond: (entity_id = pers.relation_id)
         ->  Index Scan using origo_email_address_pkey on origo_email_address ef  (cost=0.43..0.68 rows=1 width=50) (actual time=0.007..0.008 rows=1 loops=75)
               Index Cond: (em.from_id = entity_id)
         SubPlan 1
           ->  Nested Loop  (cost=0.85..16.90 rows=1 width=24) (actual time=0.012..0.014 rows=1 loops=75)
                 ->  Index Scan using origo_email_address_owner_message_id_recipient_type_address_key on origo_email_address_owner o  (cost=0.42..8.45 rows=1 width=12) (actual time=0.008..0.008 rows=1 loops=75)
                       Index Cond: ((message_id = em.entity_id) AND ((recipient_type)::text = 'TO'::text))
                 ->  Index Scan using origo_email_address_pkey on origo_email_address a  (cost=0.43..8.45 rows=1 width=28) (actual time=0.002..0.003 rows=1 loops=93)
                       Index Cond: (entity_id = o.address_id)
         SubPlan 2
           ->  Nested Loop  (cost=0.85..16.90 rows=1 width=26) (actual time=0.007..0.008 rows=1 loops=75)
                 ->  Index Scan using origo_email_address_owner_message_id_recipient_type_address_key on origo_email_address_owner o_1  (cost=0.42..8.45 rows=1 width=12) (actual time=0.004..0.004 rows=1 loops=75)
                       Index Cond: ((message_id = em.entity_id) AND ((recipient_type)::text = 'TO'::text))
                 ->  Index Scan using origo_email_address_pkey on origo_email_address a_1  (cost=0.43..8.45 rows=1 width=30) (actual time=0.002..0.002 rows=1 loops=93)
                       Index Cond: (entity_id = o_1.address_id)
         SubPlan 3
           ->  Seq Scan on origo_favourite_owner person_fav  (cost=0.00..4.75 rows=1 width=4) (actual time=0.027..0.027 rows=0 loops=75)
                 Filter: ((favourite_for = 3::bigint) AND (favourite_item = pers.entity_id))
                 Rows Removed by Filter: 183
         SubPlan 4
           ->  Seq Scan on origo_favourite_owner company_fav  (cost=0.00..4.75 rows=1 width=4) (actual time=0.023..0.023 rows=0 loops=75)
                 Filter: ((favourite_for = 3::bigint) AND (favourite_item = comp.entity_id))
                 Rows Removed by Filter: 183
 Total runtime: 3481.136 ms
(42 rows)
 
Does anyone see anything obvious or have any hints what to investigate further?
 
Thanks.
 
--
Andreas Joseph Krogh
CTO / Partner - Visena AS
Mobile: +47 909 56 963
Attachment

pgsql-performance by date:

Previous
From: Rural Hunter
Date:
Subject: Re: Very slow planning performance on partition table
Next
From: David G Johnston
Date:
Subject: Re: Query performing very bad and sometimes good