Cannot reproduce why a query is slow
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
On Thu, May 5, 2011 at 8:54 AM, Andrew Sullivan <ajs@crankycanuck.ca> wrote:
On Thu, May 05, 2011 at 08:02:46AM -0700, John Cheng wrote:
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.Just a couple ideas.
First, when you do this via command line, presumably the conditions
that set up the query aren't present. Is it possible that there's
been a lot of activity on the table leading to dead rows that have
been cleaned up by autovacuum by the time you come along? (Or that
the table has otherwise changed so that you are getting the benefit of
indexes that the query wasn't using?)I especially note that
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'))these all look like the sort of status values that might change as the
result of batch operations.Similarly, you might be running into I/O limits. If this is a large
report that is running at the same time as batch loads and so on of
updates, you can find the query is very slow just because the machine
is busy.Finally, you're not standing in line behind any locks, are you?
Anyway, those are the things I'd start with.
A
--
Andrew Sullivan
ajs@crankycanuck.ca
I have a couple of queries that allow me to see the active locks in
the database. It might help me see if these queries are blocked by
other locking queries.
In terms of IO limits, there are no other reports that are running.
What is the appropriate way to see if IO is the issue? I think the
900ms time is due to the database fetching data from disk. Can I force
the command line version to not use the memory cache and see if it
takes around 900ms in that case?
--
---
John L Cheng
Import Notes
Reply to msg id not found: 20110505155400.GI25833@shinkuro.com
On Thu, May 05, 2011 at 09:27:47AM -0700, John Cheng wrote:
I have a couple of queries that allow me to see the active locks in
the database. It might help me see if these queries are blocked by
other locking queries.
Yes. The pg_locks view is your friend here.
In terms of IO limits, there are no other reports that are running.
What is the appropriate way to see if IO is the issue? I think the
900ms time is due to the database fetching data from disk. Can I force
the command line version to not use the memory cache and see if it
takes around 900ms in that case?
No, but you could run iostat during the period that this is happening
and see whether it shows you a big spike at that time. Also, the
pg_statio_user_tables data might help you. I think to make useful
inferences, you'd probably have to clear the statistics before and
after this runs, but you could do that and then compare what you get
when you look at it by hand.
A
--
Andrew Sullivan
ajs@crankycanuck.ca
On Thu, May 5, 2011 at 10:01 AM, Andrew Sullivan <ajs@crankycanuck.ca> wrote:
On Thu, May 05, 2011 at 09:27:47AM -0700, John Cheng wrote:
I have a couple of queries that allow me to see the active locks in
the database. It might help me see if these queries are blocked by
other locking queries.Yes. The pg_locks view is your friend here.
I'm not sure locks is an issue here. I typically see
now | relname |
transactionid | locktype | pid | client_addr |
activity_start | mode | granted
-------------------------------+------------------------------------+---------------+---------------+-------+----------------+-------------------------------+------------------+---------
2011-05-05 21:36:02.739645-05 | inbound_smtp_lead_id_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_sale_date_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowShareLock | t
2011-05-05 21:36:02.739645-05 | lead |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | sale_matching_zipname_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_source_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_source_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | inbound_smtp_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_dealer_region_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_modified_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_modified_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | metadata |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | dealer_metadata_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | dealer_dealer_code_key |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_dealer_code_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | sale_matching_email_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | locality_data_postal_code_norm_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | sale_matching_alt_phone_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | config_xml_current |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_processing_state_step_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_processing_state_step_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_model_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_matching |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | metadata_key_value_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | sale_matching |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_created_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_created_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | dealer_metadata |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | sl_action_seq |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_reporting_data |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_dealer_region_area_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | dated_config_xml |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | lead_reporting_list_data |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | dealer_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | external_system |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowShareLock | t
2011-05-05 21:36:02.739645-05 | dated_config_xml_name_key |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | inbound_smtp |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | reporting_date_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | reporting_date_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | |
267993478 | transactionid | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | ExclusiveLock | t
2011-05-05 21:36:02.739645-05 | metadata_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_type_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | sale_matching_phone_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | dealer |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | sl_log_2 |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | locality_data |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | |
| virtualxid | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | ExclusiveLock | t
2011-05-05 21:36:02.739645-05 | sl_log_status |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | reporting_modified_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | reporting_modified_idx |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | RowExclusiveLock | t
2011-05-05 21:36:02.739645-05 | sale_matching_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_pkey |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
2011-05-05 21:36:02.739645-05 | mb_sale_vin_key |
| relation | 21049 | 172.16.172.233 | 2011-05-05
21:36:02.724541-05 | AccessShareLock | t
With the pid 21049 being...
now | datname | procpid | usename |
current_query | waiting | query_start |
client_addr | client_port
-------------------------------+---------+---------+---------+---------------------+---------+-------------------------------+----------------+-------------
2011-05-05 21:36:04.485478-05 | lms_kia | 7511 | slony | <IDLE>
| f | 2011-05-05 21:35:57.361982-05 | 172.16.172.247
| 34535
2011-05-05 21:36:04.485478-05 | lms_kia | 7506 | slony | <IDLE>
| f | 2011-05-05 21:36:01.361098-05 | 172.16.172.247
| 34534
2011-05-05 21:36:04.485478-05 | lms_kia | 7512 | slony | <IDLE>
| f | 2011-05-05 21:35:30.766741-05 | 172.16.172.247
| 34536
2011-05-05 21:36:04.485478-05 | lms_kia | 7513 | slony | <IDLE>
| f | 2011-05-05 21:36:03.376233-05 | 172.16.172.247
| 34537
2011-05-05 21:36:04.485478-05 | lms_kia | 7515 | slony | <IDLE>
| f | 2011-05-05 21:36:02.982066-05 | 172.16.172.246
| 49030
2011-05-05 21:36:04.485478-05 | lms_kia | 451 | slony | <IDLE>
| f | 2011-05-05 21:36:03.277023-05 | 172.16.172.246
| 59043
2011-05-05 21:36:04.485478-05 | lms_kia | 30265 | lms.kia | <IDLE>
| f | 2011-05-05 14:00:14.272421-05 | 172.16.172.233
| 46050
2011-05-05 21:36:04.485478-05 | lms_kia | 17454 | lms.kia | <IDLE>
| f | 2011-05-05 21:32:58.405183-05 | 172.16.172.234
| 43926
2011-05-05 21:36:04.485478-05 | lms_kia | 32263 | lms.kia | <IDLE>
| f | 2011-05-02 13:00:02.660461-05 | 172.16.172.233
| 35512
2011-05-05 21:36:04.485478-05 | lms_kia | 29412 | lms.kia | <IDLE>
| f | 2011-05-05 21:36:00.025726-05 | 172.16.172.234
| 52171
2011-05-05 21:36:04.485478-05 | lms_kia | 25785 | lms.kia | <IDLE>
| f | 2011-05-05 21:35:57.311665-05 | 172.16.172.233
| 47735
2011-05-05 21:36:04.485478-05 | lms_kia | 32500 | lms.kia | <IDLE>
| f | 2011-05-02 13:00:03.856441-05 | 172.16.172.233
| 35519
2011-05-05 21:36:04.485478-05 | lms_kia | 11936 | lms.kia | <IDLE>
| f | 2011-05-05 21:33:00.023601-05 | 172.16.172.233
| 56436
2011-05-05 21:36:04.485478-05 | lms_kia | 12865 | lms.kia | <IDLE>
| f | 2011-05-05 21:30:57.287412-05 | 172.16.172.233
| 56689
2011-05-05 21:36:04.485478-05 | lms_kia | 21049 | lms.kia | select
s.id, s.vin, | f | 2011-05-05 21:36:03.621931-05 |
172.16.172.233 | 58907
2011-05-05 21:36:04.485478-05 | lms_kia | 14803 | lms.kia | <IDLE>
| f | 2011-05-05 21:32:03.613924-05 | 172.16.172.234
| 47100
2011-05-05 21:36:04.485478-05 | lms_kia | 23330 | lms.kia | <IDLE>
| f | 2011-05-02 13:00:00.213037-05 | 172.16.172.233
| 60786
2011-05-05 21:36:04.485478-05 | lms_kia | 7588 | lms.kia | <IDLE>
| f | 2011-05-05 21:34:30.086489-05 | 172.16.172.233
| 39107
2011-05-05 21:36:04.485478-05 | lms_kia | 32264 | lms.kia | <IDLE>
| f | 2011-05-02 13:00:03.600691-05 | 172.16.172.233
| 35513
2011-05-05 21:36:04.485478-05 | lms_kia | 8547 | lms.kia | <IDLE>
| f | 2011-05-05 14:00:02.409241-05 | 172.16.172.233
| 36389
2011-05-05 21:36:04.485478-05 | lms_kia | 19958 | lms.kia | <IDLE>
| f | 2011-05-05 21:36:00.027759-05 | 172.16.172.233
| 59906
2011-05-05 21:36:04.485478-05 | lms_kia | 18926 | lms.kia | <IDLE>
| f | 2011-05-05 21:33:01.884495-05 | 172.16.172.234
| 53542
2011-05-05 21:36:04.485478-05 | lms_kia | 8548 | lms.kia | <IDLE>
| f | 2011-05-05 14:00:00.117233-05 | 172.16.172.233
| 36390
2011-05-05 21:36:04.485478-05 | lms_kia | 8822 | lms.kia | <IDLE>
| f | 2011-05-05 14:00:14.735311-05 | 172.16.172.233
| 36394
2011-05-05 21:36:04.485478-05 | lms_kia | 974 | lms.kia | <IDLE>
| f | 2011-05-05 21:36:00.026441-05 | 172.16.172.234
| 47237
With just one query running at this time... this is a query that runs
right after the "slow" query. Basically, these types of queries runs
serially, I don't see many instances where there are multiple
concurrent queries at the same time.
In terms of IO limits, there are no other reports that are running.
What is the appropriate way to see if IO is the issue? I think the
900ms time is due to the database fetching data from disk. Can I force
the command line version to not use the memory cache and see if it
takes around 900ms in that case?No, but you could run iostat during the period that this is happening
and see whether it shows you a big spike at that time. Also, the
pg_statio_user_tables data might help you. I think to make useful
inferences, you'd probably have to clear the statistics before and
after this runs, but you could do that and then compare what you get
when you look at it by hand.
During this time, iostat shows
Time: 09:36:00 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 1.00 0.00 5.00 0.00 24.00 9.60
0.03 8.60 3.60 1.80
sdb 0.00 7.00 0.00 8.00 0.00 60.00 15.00
0.01 1.00 1.00 0.80
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
Time: 09:36:01 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 1.00 0.00 3.00 0.00 16.00 10.67
0.02 6.67 6.67 2.00
sdb 0.00 576.00 0.00 23.00 0.00 2396.00 208.35
0.05 2.17 1.43 3.30
sdc 0.00 0.00 8.00 0.00 64.00 0.00 16.00
0.03 4.25 4.25 3.40
sdd 0.00 0.00 1.00 0.00 8.00 0.00 16.00
0.01 9.00 9.00 0.90
Time: 09:36:02 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 1.00 0.00 2.00 0.00 12.00 12.00
0.04 17.50 11.00 2.20
sdb 0.00 233.00 0.00 15.00 0.00 992.00 132.27
0.02 1.47 1.00 1.50
sdc 0.00 147.00 3.00 75.00 32.00 888.00 23.59
0.45 5.73 0.29 2.30
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
Time: 09:36:03 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 3.00 0.00 8.00 0.00 44.00 11.00
0.07 9.38 7.00 5.60
sdb 0.00 471.00 0.00 22.00 0.00 1972.00 179.27
0.06 2.50 2.14 4.70
sdc 1.00 0.00 10.00 0.00 80.00 0.00 16.00
0.04 3.50 3.50 3.50
sdd 0.00 0.00 1.00 0.00 8.00 0.00 16.00
0.00 4.00 4.00 0.40
Time: 09:36:04 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 17.00 0.00 9.00 0.00 88.00 19.56
0.09 7.44 8.67 7.80
sdb 0.00 43.00 0.00 3.00 0.00 184.00 122.67
0.00 1.00 0.67 0.20
sdc 0.00 0.00 2.00 0.00 16.00 0.00 16.00
0.01 6.50 6.50 1.30
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
Time: 09:36:05 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 8.00 0.00 8.00 0.00 80.00 20.00
0.11 17.38 6.38 5.10
sdb 0.00 157.00 0.00 10.00 0.00 668.00 133.60
0.02 2.00 1.90 1.90
sdc 0.00 0.00 3.00 0.00 32.00 0.00 21.33
0.01 3.67 3.67 1.10
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
Time: 09:36:06 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 51.00 0.00 4.00 0.00 220.00 110.00
0.03 6.50 6.00 2.40
sdb 0.00 393.00 0.00 20.00 0.00 1652.00 165.20
0.03 1.45 1.15 2.30
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdd 0.00 42.00 3.00 25.00 152.00 272.00 30.29
0.06 2.25 1.11 3.10
This means between 600 to 2000kb of writes a second. 2000kb/second at
this time is the highest today. Munin shows that DB averages 186kb
read/265kb write per second.
I'll take a look into the pg_statio_user_tables and related tables
tomorrow. It's the first time I've read about them, but any pointers
on what I should focus on would be great (boy, there's always
something new to learn).
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 ascSort (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
Dne 5.5.2011 17:02, John Cheng napsal(a):
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?
I'd guess two possible causes - resource utilization and unexpected plan
changes.
Resource usually means there's too much I/O so the query is slow, but
when you try it later the drives are idle and query runs much faster.
Run some monitoring, e.g. even a simple 'iostat -x' or 'dstat' output
might be sufficient. Once the slow query happens, try to correlate it to
the CPU / disk activity.
The unexpected plan change is usually caused by autovacuum/autoanalyze
collecting skewed data for some reason, resulting in bad plan choice.
Then the autovacuum runs again and you get different (much better) plan.
This can be detected using the auto_explain contrib module, as someone
already recommended.
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.
I generally do recommend using explain.depesz.com to post explain plans,
especially in case of complex queries. I've posted your query and this
is the result
http://explain.depesz.com/s/gJO
Not sure if it's relevant to your issue (probably not), but the bitmap
index scans are significantly overestimated. Not sure if the overlap
operator affects the estimate accuracy ...
BTW what postgresql version is this? How large the database is, how much
RAM is available? What is the size of shared_buffers?
regards
Tomas
Sorry about the long wait between reply.
On Sat, May 7, 2011 at 2:36 PM, Tomas Vondra <tv@fuzzy.cz> wrote:
Resource usually means there's too much I/O so the query is slow, but
when you try it later the drives are idle and query runs much faster.
Run some monitoring, e.g. even a simple 'iostat -x' or 'dstat' output
might be sufficient. Once the slow query happens, try to correlate it to
the CPU / disk activity.
I am unsure if disk IO could be a part of the problem. iostat shows a max of
~2000kb/second write. This query gets during a batch of insert/update
process (every 5 minutes or so, we batch process a list of 20 or so xmls,
i.e., "leads"). During the batch processing, iostat shows pretty low usage.
avg-cpu: %user %nice %system %iowait %steal %idle
4.38 0.00 0.12 0.62 0.00 94.88
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 0.99 0.00 5.94 0.00 55.45 9.33
0.10 16.17 6.17 3.66
sdb 0.00 172.28 0.00 11.88 0.00 1473.27 124.00
0.03 2.42 1.08 1.29
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
8.35 0.00 0.37 0.37 0.00 90.90
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdb 0.00 621.00 0.00 23.00 0.00 5152.00 224.00 0.08
3.52 1.22 2.80
sdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdd 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
avg-cpu: %user %nice %system %iowait %steal %idle
9.62 0.00 0.12 1.88 0.00 88.38
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz
avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00
0.00 0.00 0.00 0.00
sdb 0.00 73.00 0.00 9.00 0.00 656.00 72.89
0.01 1.33 1.00 0.90
sdc 0.00 200.00 20.00 129.00 304.00 2632.00 19.70
1.22 8.16 0.68 10.20
sdd 0.00 0.00 9.00 0.00 120.00 0.00 13.33
0.04 4.67 4.56 4.10
The 'atop' command shows low disk activity ~2%, but I'm not sure how
accurate atop is. If I were to run a similar query from the command line
while the batch job is running, I still get a 50ms execution time.
CPU usage does goes up a lot during this time. There are 8 cores and 1 of
the cores shoots up to ~97%. The process updates XML records in the database
and performs dozens of xpath based queries to pull data out of the xml into
relational tables. These extractions are performed with pgplsql triggers and
Postgres xpath functions. Hence the spike in CPU usage during that time.
The unexpected plan change is usually caused by autovacuum/autoanalyze
collecting skewed data for some reason, resulting in bad plan choice.
Then the autovacuum runs again and you get different (much better) plan.
This can be detected using the auto_explain contrib module, as someone
already recommended.
We are using Postgres 8.3 and I don't believe the autoexplain contrib module
is available for 8.3.
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.I generally do recommend using explain.depesz.com to post explain plans,
especially in case of complex queries. I've posted your query and this
is the resulthttp://explain.depesz.com/s/gJO
Not sure if it's relevant to your issue (probably not), but the bitmap
index scans are significantly overestimated. Not sure if the overlap
operator affects the estimate accuracy ...BTW what postgresql version is this? How large the database is, how much
RAM is available? What is the size of shared_buffers?
I am loving explain.depesz.com!
We are using Postgres 8.3.This system has 16GB of RAM. The database is
114GB. shared_buffers is set to 2000MB. A possibly related note... the
'effective_cache_size' setting. The previous admin set it to 8000MB. The
free command shows 13.8GB cache, 397MB buffer. I wonder if changing the
effective_cache_size can improve query planning.