Re: Cannot reproduce why a query is slow

On Thu, May 5, 2011 at 10:01 AM, Andrew Sullivan <ajs(at)crankycanuck(dot)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).