Message-ID: <4B8BFDEF.1080006@acrys.com>
Date: Mon, 01 Mar 2010 18:48:31 +0100
From: Rainer Pruy <Rainer.Pruy@Acrys.COM>
Organization: Acrys Consult GmbH & Co. KG
User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; de;
	rv:1.9.1.5) Gecko/20091130 SUSE/3.0.0-1.1.1 Lightning/1.0b1
	Thunderbird/3.0
MIME-Version: 1.0
To: Tom Lane <tgl@sss.pgh.pa.us>
CC: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Re: Query slowing down significantly??
References: <4B8BB815.4060104@acrys.com> <17910.1267460132@sss.pgh.pa.us>
In-Reply-To: <17910.1267460132@sss.pgh.pa.us>
Content-Type: text/plain; charset=ISO-8859-15
Content-Transfer-Encoding: 7bit

Thanks for the hint.
I should have been considering that in the first place.
(But the obvious is easily left unrecognised..)

The prepared statement gives:

                                                                        QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.00..25.18 rows=2 width=175) (actual time=36.116..49.998 rows=1 loops=1)
   ->  Index Scan using x_context_01 on context c  (cost=0.00..10.76 rows=2 width=67) (actual time=0.029..6.947 rows=12706 loops=1)
         Index Cond: ((contextid)::text = $1)
   ->  Index Scan using x_fk_context_hierarchy_02 on context_hierarchy h  (cost=0.00..7.20 rows=1 width=108) (actual time=0.003..0.003
rows=0 loops=12706)
         Index Cond: (h.contextidx = c.idx)
         Filter: (((h.hierarchyname)::text = $2) AND (h.parentidx = $3))
 Total runtime: 50.064 ms
(7 rows)


And that is quite a bad plan given the current distribution of values.

Regards,
Rainer

Am 01.03.2010 17:15, schrieb Tom Lane:
> Rainer Pruy <Rainer.Pruy@Acrys.COM> writes:
>> Normally the following Query behaves well:
> 
>> select c.*, h.*
>> from Context c, Context_Hierarchy h
>> where c.Idx = h.ContextIdx and c.ContextId='testID' and h.HierarchyName='InsuranceHierarchy' and h.ParentIdx=49292395
>> ;
>>                                                                       QUERY PLAN
>> ------------------------------------------------------------------------------------------------------------------------------------------------------
>>  Nested Loop  (cost=0.00..43.57 rows=4 width=175) (actual time=0.291..0.293 rows=1 loops=1)
>>    ->  Index Scan using uk_context_hierarchy_01 on context_hierarchy h  (cost=0.00..14.76 rows=4 width=108) (actual time=0.169..0.169
>> rows=1 loops=1)
>>          Index Cond: (((hierarchyname)::text = 'InsuranceHierarchy'::text) AND (parentidx = 49292395))
>>    ->  Index Scan using pk_context on context c  (cost=0.00..7.20 rows=1 width=67) (actual time=0.110..0.111 rows=1 loops=1)
>>          Index Cond: (c.idx = h.contextidx)
>>          Filter: ((c.contextid)::text = 'testID'::text)
>>  Total runtime: 0.388 ms
>> (7 rows)
> 
>> (From a freshly started PG)
> 
>> However during a long term read-only transaction (actually just bout 15min)
>> (the transaction is issuing about 10k-20k of such queries among others)
>> PG is logging a number of the following:
> 
>> Mar  1 09:58:09 gaia postgres[20126]: [25-1] LOG:  00000: duration: 343.663 ms  execute S_5: select c.*, h.Idx as h_Idx, h.WbuIdx as
>> h_WbuIdx, h.OrigWbuIdx as h_OrigWbuIdx, h.Ts as h_Ts, h.
>> UserId as h_UserId, h.ParentIdx as h_ParentIdx, h.ContextIdx as h_ContextIdx, h.HierarchyName as h_HierarchyName, h.HierarchyPath as
>> h_HierarchyPath from Context c, Context_Hierarchy h wher
>> e c.Idx = h.ContextIdx and c.ContextId=$1 and h.HierarchyName=$2 and h.ParentIdx=$3
>> Mar  1 09:58:09 gaia postgres[20126]: [25-2] DETAIL:  parameters: $1 = 'testID', $2 = 'InsuranceHierarchy', $3 = '49292395'
>> Mar  1 09:58:09 gaia postgres[20126]: [25-3] LOCATION:  exec_execute_message, postgres.c:1988
> 
> That's not the same query at all, and it may not be getting the same
> plan.  What you need to do to check the plan is to try PREPARE-ing
> and EXPLAIN EXECUTE-ing the query with the same parameter symbols
> as are actually used in the application-issued query.
> 
> You might be entertained by the recent thread on -hackers about
> "Avoiding bad prepared-statement plans" ...
> 
> 			regards, tom lane