Inconsistent query performance

From: Ramsey Gurley <rgurley(at)smarthealth(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: Inconsistent query performance
Date: 2013-04-08 22:08:17
Message-ID: 3B611016-8DC4-4CC7-8A97-567122E202B9@smarthealth.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi all,

I'm having issues with slow queries using postgres, and I'm finding some of the issues difficult to reproduce. My application logs slow queries for me, but often, when I go back to run explain analyze on the query it is very fast. I assume this is due to some sort of caching. Here is an example:

sqlLogging _valuesForSQL ran 116509ms with sql string:

select t1.transaction_id, t1.campaign_definition_id, t1.campaign_detail_number, t2.name as campaign_name, t1.communication_type, t1.delivery_error, t1.call_result into temporary activity_transactions_temp from customer.customer_transactions t1, campaign.campaign_definitions t2 where t1.customer_id = 2577 and t1.timestamp >= '04/08/2013' and t1.timestamp < '04/09/2013' and t1.campaign_definition_id = 23 and t1.campaign_definition_id = t2.campaign_definition_id order by campaign_name, communication_type;

But if I run an explain analyze on that I get

"Sort (cost=18.08..18.08 rows=1 width=89) (actual time=767.051..767.061 rows=17 loops=1)"
" Sort Key: t2.name, t1.communication_type"
" Sort Method: quicksort Memory: 26kB"
" -> Nested Loop (cost=0.00..18.07 rows=1 width=89) (actual time=758.421..766.881 rows=17 loops=1)"
" -> Index Scan using timestamp_only_ndx on customer_transactions t1 (cost=0.00..9.79 rows=1 width=69) (actual time=79.771..88.119 rows=17 loops=1)"
" Index Cond: (("timestamp" >= '2013-04-08 00:00:00'::timestamp without time zone) AND ("timestamp" < '2013-04-09 00:00:00'::timestamp without time zone))"
" Filter: ((customer_id = 2577) AND (campaign_definition_id = 23))"
" -> Index Scan using campaign_definitions_campaign_definition_id_key on campaign_definitions t2 (cost=0.00..8.27 rows=1 width=24) (actual time=39.922..39.923 rows=1 loops=17)"
" Index Cond: (t2.campaign_definition_id = 23)"
"Total runtime: 770.830 ms"

Is there anything that can tell me why this query took 117 seconds, and what, if anything, can be done to fix it?

Here's another much more simple one:

expression took 20147 ms:

SELECT t0.appointment_id, t0.customer_id, t0.event_date, t0.patient_id, t0.transaction_id FROM customer.customer_transactions_detail t0 WHERE (t0.patient_id = 7441 AND t0.customer_id = 2965)

"Index Scan using customer_id_patient_id_idx on customer_transactions_detail t0 (cost=0.00..10.22 rows=1 width=24) (actual time=35.952..99.487 rows=14 loops=1)"
" Index Cond: ((customer_id = 2965) AND (patient_id = 7441))"
"Total runtime: 99.537 ms"

So it took 20 seconds at 12:18pm today, but now it takes ~100ms.

Thanks,

Ramsey

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Kevin Grittner 2013-04-08 22:09:07 Re: pg_stat_get_last_vacuum_time(): why non-FULL?
Previous Message David Kerr 2013-04-08 21:59:56 Re: AWS and postgres issues