Thread: 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
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 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
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.
I generally do recommend using explain.depesz.com to post explain plans,
> 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.
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?
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.