Re: Cannot reproduce why a query is slow

Try auto_explain module.

2011/5/5, John Cheng <johnlicheng(at)gmail(dot)com>:
> 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
>
> --
> Sent via pgsql-general mailing list (pgsql-general(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general
>

--
------------
pasman