Received: from maia.hub.org (unknown [200.46.204.183])
	by mail.postgresql.org (Postfix) with ESMTP id 1D9CB6355E0
	for <pgsql-performance-postgresql.org@mail.postgresql.org>;
	Wed, 31 Mar 2010 15:40:29 -0300 (ADT)
Received: from mail.postgresql.org ([200.46.204.86])
	by maia.hub.org (mx1.hub.org [200.46.204.183]) (amavisd-maia,
	port 10024) with ESMTP id 00359-01
	for <pgsql-performance-postgresql.org@mail.postgresql.org>;
	Wed, 31 Mar 2010 18:40:18 +0000 (UTC)
X-Greylist: from auto-whitelisted by SQLgrey-1.7.6
Received: from smtp1.ca.com (smtp1.ca.com [141.202.248.21])
	by mail.postgresql.org (Postfix) with ESMTP id 06252636E8C
	for <pgsql-performance@postgresql.org>;
	Wed, 31 Mar 2010 15:11:50 -0300 (ADT)
Received: from athena.ca.com ([130.200.164.17]) by smtp1.ca.com with Microsoft
	SMTPSVC(6.0.3790.3959); Wed, 31 Mar 2010 14:11:49 -0400
Message-ID: <4BB3902D.7010205@ca.com>
Date: Wed, 31 Mar 2010 11:10:53 -0700
From: Brian Cox <brian.cox@ca.com>
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US;
	rv:1.9.1.5) Gecko/20091204 Lightning/1.0b1 Thunderbird/3.0
MIME-Version: 1.0
To: "David Wilson [david.t.wilson@gmail.com]" <david.t.wilson@gmail.com>
CC: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Re: query has huge variance in execution times
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
X-OriginalArrivalTime: 31 Mar 2010 18:11:49.0443 (UTC)
	FILETIME=[A1DD7930:01CAD0FD]
X-Virus-Scanned: Maia Mailguard 1.0.1
X-Spam-Status: No, hits=-0.185 tagged_above=-10 required=5
	tests=BAYES_40=-0.185
X-Spam-Level: 
X-Archive-Number: 201003/410
X-Sequence-Number: 38235

On 03/31/2010 12:37 AM, David Wilson [david.t.wilson@gmail.com] wrote:
> These won't necessarily get the same plan. If you want to see what plan
> the prepared query is getting, you'll need to prepare it ("prepare foo
> as <query>") and then explain *that* via "explain execute foo".
>
> The prepared version likely has a much more generic plan, whereas the
> regular query gets optimized for the actual values provided.

I didn't know this. Thanks. The plans are indeed different:

cemdb=# prepare sq as select b.ts_id from ts_stats_tranunit_user_daily 
b, ts_stats_tranunit_user_interval c where b.ts_transet_incarnation_id = 
c.ts_transet_incarnation_id and b.ts_tranunit_id = c.ts_tranunit_id and 
b.ts_user_incarnation_id = c.ts_user_incarnation_id and 
c.ts_interval_start_time >= $1 and c.ts_interval_start_time < $2 and 
b.ts_interval_start_time >= $3 and b.ts_interval_start_time < $4;
cemdb=# explain execute sq('2010-3-29 01:00', '2010-3-29 02:00', 
'2010-3-29', '2010-3-30'); 
                                       QUERY PLAN 
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Merge Join  (cost=7885.37..8085.91 rows=30 width=8)
    Merge Cond: ((b.ts_transet_incarnation_id = 
c.ts_transet_incarnation_id) AND (b.ts_tranunit_id = c.ts_tranunit_id) 
AND (b.ts_user_incarnation_id = c.ts_user_incarnation_id))
    ->  Sort  (cost=1711.82..1716.81 rows=3994 width=32)
          Sort Key: b.ts_transet_incarnation_id, b.ts_tranunit_id, 
b.ts_user_incarnation_id
          ->  Index Scan using ts_stats_tranunit_user_daily_starttime on 
ts_stats_tranunit_user_daily b  (cost=0.00..1592.36 rows=3994 width=32)
                Index Cond: ((ts_interval_start_time >= $3) AND 
(ts_interval_start_time < $4))

cemdb=# explain select b.ts_id from ts_stats_tranunit_user_daily b, 
ts_stats_tranunit_user_interval c where b.ts_transet_incarnation_id = 
c.ts_transet_incarnation_id and b.ts_tranunit_id = c.ts_tranunit_id and 
b.ts_user_incarnation_id = c.ts_user_incarnation_id and 
c.ts_interval_start_time >= '2010-3-29 01:00' and 
c.ts_interval_start_time < '2010-3-29 02:00' and 
b.ts_interval_start_time >= '2010-3-29' and b.ts_interval_start_time < 
'2010-3-30';
 
                    QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Hash Join  (cost=291965.90..335021.46 rows=13146 width=8)
    Hash Cond: ((c.ts_transet_incarnation_id = 
b.ts_transet_incarnation_id) AND (c.ts_tranunit_id = b.ts_tranunit_id) 
AND (c.ts_user_incarnation_id = b.ts_user_incarnation_id))
    ->  Index Scan using ts_stats_tranunit_user_interval_starttime on 
ts_stats_tranunit_user_interval c  (cost=0.00..11783.36 rows=88529 width=24)
          Index Cond: ((ts_interval_start_time >= '2010-03-29 
01:00:00-07'::timestamp with time zone) AND (ts_interval_start_time < 
'2010-03-29 02:00:00-07'::timestamp with time zone))
    ->  Hash  (cost=285681.32..285681.32 rows=718238 width=32)
          ->  Index Scan using ts_stats_tranunit_user_daily_starttime on 
ts_stats_tranunit_user_daily b  (cost=0.00..285681.32 rows=718238 width=32)
                Index Cond: ((ts_interval_start_time >= '2010-03-29 
00:00:00-07'::timestamp with time zone) AND (ts_interval_start_time < 
'2010-03-30 00:00:00-07'::timestamp with time zone))
(7 rows)

    ->  Sort  (cost=6173.55..6218.65 rows=36085 width=24)
          Sort Key: c.ts_transet_incarnation_id, c.ts_tranunit_id, 
c.ts_user_incarnation_id
          ->  Index Scan using ts_stats_tranunit_user_interval_starttime 
on ts_stats_tranunit_user_interval c  (cost=0.00..4807.81 rows=36085 
width=24)
                Index Cond: ((ts_interval_start_time >= $1) AND 
(ts_interval_start_time < $2))
(10 rows)

I notice that the row estimates are substantially different; this is due 
to the lack of actual values?

But, this prepared query runs in ~4 secs:

[root@rdl64xeoserv01 log]# cat /tmp/select.sql
prepare sq as select b.ts_id from ts_stats_tranunit_user_daily b, 
ts_stats_tranunit_user_interval c where b.ts_transet_incarnation_id = 
c.ts_transet_incarnation_id and b.ts_tranunit_id = c.ts_tranunit_id and 
b.ts_user_incarnation_id = c.ts_user_incarnation_id and 
c.ts_interval_start_time >= $1 and c.ts_interval_start_time < $2 and 
b.ts_interval_start_time >= $3 and b.ts_interval_start_time < $4;
execute sq('2010-3-29 01:00', '2010-3-29 02:00', '2010-3-29', '2010-3-30

[root@rdl64xeoserv01 log]# time PGPASSWORD=quality psql -U postgres -d 
cemdb -f /tmp/select.sql  > /tmp/select1.txt 2>&1
real    0m4.131s
user    0m0.119s
sys     0m0.007s

so the question still remains: why did it take > 20 mins? To see if it 
was due to autovacuum running ANALYZE, I turned off autovacuum, created 
a table using SELECT * INTO temp FROM ts_stats_tranunit_user_daily, 
added the index on ts_interval_start_time and ran the prepared query 
with temp, but the query completed in a few secs.

Brian