pg.ddx.io pgsql-performance@postgresql.org mailing list archivehelp / color / mirror / Atom feed
Query performing very bad and sometimes good 3+ messages / 3 participants [nested] [flat]
* Query performing very bad and sometimes good @ 2014-08-05 21:38 Andreas Joseph Krogh <andreas@visena.com> 0 siblings, 2 replies; 3+ messages in thread From: Andreas Joseph Krogh @ 2014-08-05 21:38 UTC (permalink / raw) To: 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 andreas@visena.com <mailto:andreas@visena.com> www.visena.com <https://www.visena.com; <https://www.visena.com; ^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Query performing very bad and sometimes good @ 2014-08-06 00:16 David G Johnston <david.g.johnston@gmail.com> parent: Andreas Joseph Krogh <andreas@visena.com> 1 sibling, 0 replies; 3+ messages in thread From: David G Johnston @ 2014-08-06 00:16 UTC (permalink / raw) To: pgsql-performance 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-tp5813831p58138... Sent from the PostgreSQL - performance mailing list archive at Nabble.com. -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance ^ permalink raw reply [nested|flat] 3+ messages in thread
* Re: Query performing very bad and sometimes good @ 2014-08-06 14:04 Kevin Grittner <kgrittn@ymail.com> parent: Andreas Joseph Krogh <andreas@visena.com> 1 sibling, 0 replies; 3+ messages in thread From: Kevin Grittner @ 2014-08-06 14:04 UTC (permalink / raw) To: Andreas Joseph Krogh <andreas@visena.com>; pgsql-performance 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 -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance ^ permalink raw reply [nested|flat] 3+ messages in thread
end of thread, other threads:[~2014-08-06 14:04 UTC | newest] Thread overview: 3+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2014-08-05 21:38 Query performing very bad and sometimes good Andreas Joseph Krogh <andreas@visena.com> 2014-08-06 00:16 ` David G Johnston <david.g.johnston@gmail.com> 2014-08-06 14:04 ` Kevin Grittner <kgrittn@ymail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions for how to clone and mirror all data and code used for this inbox