Thread: Query performing very bad and sometimes good

Query performing very bad and sometimes good

From

Andreas Joseph Krogh

Date:

06 August 2014, 00:38:59

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

andreas@visena.com

www.visena.com

Attachment

msg-1552478-3.png

Re: Query performing very bad and sometimes good

From

David G Johnston

Date:

06 August 2014, 03:16:38

Andreas Joseph Krogh-2 wrote
> 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    

9.3.2 is not release-worthy....


> Bad:
> 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)
>
>>>Add 4 new records<<
>
> Good (-ish):
> 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)

The plans appear to be basically identical - and the queries/data as well
aside from the addition of 4 more unmatched records.

The difference between the two is likely attributable to system load
variations combined with the effect of caching after running the query the
first (slow) time.

Doing OFFSET/LIMIT pagination can be problematic so I'd be curious what
would happen if you got rid of it.  In this specific case the result set is
only 75 with 101 allowed anyway.

The left joins seem to be marginal so I'd toss those out and optimize the
inner joins and, more likely, the correlated subqueries in the select list.
You need to avoid nested looping over 300,000+ records somehow - though I'm
not going to be that helpful in the actual how part...

Note that in the inner-most loop the actual time for the cached data is half
of the non-cached data.  While both are quite small (0.002/0.004) the
300,000+ loops do add up.  The same likely applies to the other planning
nodes but I didn't dig that deep.

David J.




--
View this message in context:
http://postgresql.1045698.n5.nabble.com/Query-performing-very-bad-and-sometimes-good-tp5813831p5813847.html
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.

Re: Query performing very bad and sometimes good

From

Kevin Grittner

Date:

06 August 2014, 17:04:40

Andreas Joseph Krogh <andreas@visena.com> wrote:

> Some-times it performs much better (but still not good)

As has already been suggested, that difference is almost certainly
due to differences in how much of the necessary data is cached or
what the query is competing with.

> Does anyone see anything obvious or have any hints what to
> investigate further?

We need more information to be able to say much.  Please review
this page:

http://wiki.postgresql.org/wiki/SlowQueryQuestions

Knowing more about the hardware and the tables (including all
indexes) would help a lot, as well as all non-default configuration
settings.  In particular, I'm curious whether there is an index on
the message_id column of origo_email_delivery.

--
Kevin Grittner
EDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company