Query slowing down significantly?? - Mailing list pgsql-performance

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.HierarchyPathas 
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