Cannot reproduce why a query is slow

From: John Cheng <johnlicheng(at)gmail(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: Cannot reproduce why a query is slow
Date: 2011-05-05 15:02:46
Message-ID: BANLkTinAqBeBk7Gaw2mec1cLeNMqqz71yg@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi,
We have certain types of query that seems to take about 900ms to run
according to postgres logs. When I try to run the same query via
command line with "EXPLAIN ANALYZE", the query finishes very quickly.
What should I do to try to learn more about why it is running slowly?

The query is a bit complex, as it is generated by code, but I tried to
format it for easier reading. I've also replaced actual data with fake
data to protected personal information.

EXPLAIN ANALYZE
SELECT lm.lead_id as leadId,
lm.reporting_date as createdDay,
lrd.processing_state as processingState,
lrd.dealer_code as dealerCode
FROM lead_matching lm inner join lead_reporting_data lrd
on lrd.lead_id = lm.lead_id
WHERE ((lm.reporting_date >= '2011-04-05') AND (lm.reporting_date <=
'2011-05-05')
AND (lrd.dealer_region = 'SO') AND (lrd.dealer_area = '02')
AND (lm.lead_id < 2645059)
AND (lrd.processing_state <> 'REJECTED') AND
((lrd.processing_state = 'NEW') OR (lrd.processing_state =
'PROCESSING') OR (lrd.processing_state = 'DELIVER') OR
(lrd.processing_state = 'DELIVERED') OR (lrd.processing_state =
'DONE') OR (lrd.processing_state = 'ERROR'))
AND ((lm.customer_phone && '{5555555555}') OR
(lm.customer_email && '{lisasmith(at)example(dot)com}') OR
((lm.customer_lname = 'smith') AND (lm.customer_postal_code
&& '{4444,4444}') AND
((lm.customer_fname = 'l') OR (lm.customer_address &&
'{3333,3333}')))))
ORDER BY lm.reporting_date asc, lrd.lead_id asc

Sort (cost=17382.02..17382.06 rows=16 width=31) (actual
time=54.762..54.762 rows=0 loops=1)
Sort Key: lm.reporting_date, lrd.lead_id
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=3070.50..17381.70 rows=16 width=31) (actual
time=54.749..54.749 rows=0 loops=1)
-> Bitmap Heap Scan on lead_matching lm
(cost=3070.50..7256.87 rows=1157 width=12) (actual time=54.746..54.746
rows=0 loops=1)
Recheck Cond: (((customer_phone &&
'{5555555555}'::text[]) OR (customer_email &&
'{lisasmith(at)example(dot)com}'::text[]) OR ((customer_lname)::text =
'smith'::text)) AND (reporting_date >= '2011-04-05'::date) AND
(reporting_date <= '2011-05-05'::date))
Filter: ((lead_id < 2645059) AND ((customer_phone &&
'{5555555555}'::text[]) OR (customer_email &&
'{lisasmith(at)example(dot)com}'::text[]) OR (((customer_lname)::text =
'smith'::text) AND (customer_postal_code && '{4444,4444}'::text[]) AND
((customer_fname = 'l'::bpchar) OR (customer_address &&
'{3333,3333}'::text[])))))
-> BitmapAnd (cost=3070.50..3070.50 rows=1164
width=0) (actual time=54.358..54.358 rows=0 loops=1)
-> BitmapOr (cost=649.49..649.49 rows=26456
width=0) (actual time=0.814..0.814 rows=0 loops=1)
-> Bitmap Index Scan on
lead_matching_phone_idx (cost=0.00..315.54 rows=13182 width=0)
(actual time=0.055..0.055 rows=4 loops=1)
Index Cond: (customer_phone &&
'{5555555555}'::text[])
-> Bitmap Index Scan on
lead_matching_email_idx (cost=0.00..327.57 rows=13182 width=0)
(actual time=0.029..0.029 rows=1 loops=1)
Index Cond: (customer_email &&
'{lisasmith(at)example(dot)com}'::text[])
-> Bitmap Index Scan on
lead_matching_name_idx (cost=0.00..5.51 rows=92 width=0) (actual
time=0.726..0.726 rows=1225 loops=1)
Index Cond: ((customer_lname)::text =
'smith'::text)
-> Bitmap Index Scan on
lead_matching_reporting_date_idx (cost=0.00..2420.48 rows=116019
width=0) (actual time=52.931..52.931 rows=114892 loops=1)
Index Cond: ((reporting_date >=
'2011-04-05'::date) AND (reporting_date <= '2011-05-05'::date))
-> Index Scan using lead_reporting_data_pkey on
lead_reporting_data lrd (cost=0.00..8.74 rows=1 width=19) (never
executed)
Index Cond: (lrd.lead_id = lm.lead_id)
Filter: (((lrd.processing_state)::text <>
'REJECTED'::text) AND ((lrd.dealer_region)::text = 'SO'::text) AND
((lrd.dealer_area)::text = '02'::text) AND
(((lrd.processing_state)::text = 'NEW'::text) OR
((lrd.processing_state)::text = 'PROCESSING'::text) OR
((lrd.processing_state)::text = 'DELIVER'::text) OR
((lrd.processing_state)::text = 'DELIVERED'::text) OR
((lrd.processing_state)::text = 'DONE'::text) OR
((lrd.processing_state)::text = 'ERROR'::text)))

The lead_matching and lead_reporting_data table both contain 2637054
records. They look like:

Table "public.lead_matching"
Column | Type | Modifiers
----------------------+------------------------+-----------
lead_id | bigint | not null
reporting_date | date |
customer_fname | character(1) |
customer_lname | character varying(128) |
customer_postal_code | text[] |
customer_email | text[] |
customer_phone | text[] |
customer_address | text[] |
dealer_group | character varying(16) |
Indexes:
"lead_matching_pkey" PRIMARY KEY, btree (lead_id)
"lead_matching_address_idx" gin (customer_address)
"lead_matching_customer_postal_code_idx" btree
(customer_postal_code) WHERE reporting_date >= '2011-02-01'::date
"lead_matching_email_idx" gin (customer_email)
"lead_matching_name_idx" btree (customer_lname, customer_fname)
"lead_matching_phone_idx" gin (customer_phone)
"lead_matching_reporting_date_idx" btree (reporting_date) WHERE
reporting_date >= '2011-02-01'::date
Foreign-key constraints:
"fk_lead_matching_lead" FOREIGN KEY (lead_id) REFERENCES lead(id)
ON DELETE CASCADE
Triggers:
_lms_logtrigger AFTER INSERT OR DELETE OR UPDATE ON lead_matching
FOR EACH ROW EXECUTE PROCEDURE _lms.logtrigger('_lms', '80', 'k')
Disabled triggers:
_lms_denyaccess BEFORE INSERT OR DELETE OR UPDATE ON lead_matching
FOR EACH ROW EXECUTE PROCEDURE _lms.denyaccess('_lms')

Table "public.lead_reporting_data"
Column | Type | Modifiers
----------------------+--------------------------+-----------
lead_id | bigint | not null
reporting_date | date |
model | character varying(50) |
dealer_code | character varying(32) |
dealer_region | character varying(10) |
dealer_area | character varying(10) |
dealer_region_area | character varying(21) |
customer_postal_code | character varying(6) |
customer_fname | text |
customer_lname | text |
delivery_date | timestamp with time zone |
oem_type | text |
oem_subtype | text |
typeflags | text[] |
unique_all | boolean | not null
unique_region | boolean | not null
unique_area | boolean | not null
unique_dealer | boolean | not null
distance_to_dealer | double precision |
delivery_meth | text |
processing_state | character varying(20) | not null
model_year | integer |
Indexes:
"lead_reporting_data_pkey" PRIMARY KEY, btree (lead_id),
tablespace "lms_index"
"lead_reporting_data_dealer_code_idx" btree (dealer_code),
tablespace "lms_index"
"lead_reporting_data_dealer_region_area_idx" btree
(dealer_region_area), tablespace "lms_index"
"lead_reporting_data_dealer_region_idx" btree (dealer_region),
tablespace "lms_index"
"lead_reporting_data_model_idx" btree (model), tablespace "lms_index"
"lead_reporting_data_processing_state_idx" btree
(processing_state) WHERE processing_state::text <> 'DONE'::text AND
processing_state::text <> 'FORWARDED'::text AND processing_state::text
<> 'USED_DONE'::text, tablespace "lms_index"
"lead_reporting_data_reporting_date_idx" btree (reporting_date),
tablespace "lms_index"
"lead_reporting_data_typeflags_idx" gin (typeflags), tablespace "lms_index"
Foreign-key constraints:
"fk_lead_reporting_data_lead" FOREIGN KEY (lead_id) REFERENCES
lead(id) ON DELETE CASCADE
Triggers:
_lms_logtrigger AFTER INSERT OR DELETE OR UPDATE ON
lead_reporting_data FOR EACH ROW EXECUTE PROCEDURE
_lms.logtrigger('_lms', '25', 'k')
set_lead_reporting_data_distance_to_dealer BEFORE INSERT OR UPDATE
ON lead_reporting_data FOR EACH ROW EXECUTE PROCEDURE
update_lead_reporting_data_distance_to_dealer()
Disabled triggers:
_lms_denyaccess BEFORE INSERT OR DELETE OR UPDATE ON
lead_reporting_data FOR EACH ROW EXECUTE PROCEDURE
_lms.denyaccess('_lms')

--
---
John L Cheng

Responses

Browse pgsql-general by date

  From Date Subject
Next Message John Cheng 2011-05-05 15:21:22 Re: permission denied for schema even as superuser.
Previous Message Cédric Villemain 2011-05-05 14:46:05 Re: undead index