Re: Cannot reproduce why a query is slow

Try auto_explain module.

2011/5/5, John Cheng <johnlicheng@gmail.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@example.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@example.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@example.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@example.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@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-general
>


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