Message-ID: <4B8BB815.4060104@acrys.com>
Date: Mon, 01 Mar 2010 13:50:29 +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: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Query slowing down significantly??
Content-Type: text/plain; charset=ISO-8859-15
Content-Transfer-Encoding: 7bit

Hi all,

I'm quite puzzled by the following observation.
The behaviour is observed on a production system (Linux, PG 8.3.5)
and also on a test system (NetBSD 5.0.2, PG 8.4.2).

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

(About 200 in the current case.)

This is from the test system. The given transaction was the only activity on the system at that time.

While the transaction was still active,
I issued  the query in parallel yielding the following plan (based on the logged message above):

                                                                      QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop  (cost=0.00..43.57 rows=4 width=175) (actual time=21.809..21.811 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=21.629..21.629 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.169..0.169 rows=1 loops=1)
         Index Cond: (c.idx = h.contextidx)
         Filter: ((c.contextid)::text = 'testID'::text)
 Total runtime: 22.810 ms
(7 rows)

This still looks reasonable and is far from the >300ms as logged.
All this happens after the read-only transaction was active for a while.


Any idea where to look for an explanation?
Or what parameters could shed some light on the issue?


Regards,
Rainer