Cannot reproduce why a query is slow - Mailing list 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@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