Thread: Query slowing down significantly??
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
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.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
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
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=12706loops=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.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
>
> 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
Rainer Pruy <Rainer.Pruy@Acrys.COM> writes:
> The prepared statement gives:
> ...
> And that is quite a bad plan given the current distribution of values.
Yeah. The planner really needs to know the actual parameter values in
order to pick the best plan for this case.
One thing that you might be able to do to avoid giving up on prepared
statements entirely is to use an "unnamed" rather than named prepared
statement here. That will lead to the query plan being prepared only
when the parameter values are made available, rather than in advance.
It'd depend on what client library you're using whether this is a simple
change or not.
regards, tom lane
I'm already at it It is a Java app, using jdbc, but through a proprietary persistence framework. I'm just busy evaluating the effects on the app of prohibiting prepared statements via jdbc. If this is not worthwhile, I'm bound to some expensive reorganizations, sigh. Nevertheless, thanks for your help in reminding me about obvious use of prepared statements. Rainer PS: I've just read the thread on "Avoiding bad prepared-statement plans". Very interesting. Will track this... Am 01.03.2010 19:15, wrote Tom Lane: > Rainer Pruy <Rainer.Pruy@Acrys.COM> writes: >> The prepared statement gives: >> ... >> And that is quite a bad plan given the current distribution of values. > > Yeah. The planner really needs to know the actual parameter values in > order to pick the best plan for this case. > > One thing that you might be able to do to avoid giving up on prepared > statements entirely is to use an "unnamed" rather than named prepared > statement here. That will lead to the query plan being prepared only > when the parameter values are made available, rather than in advance. > It'd depend on what client library you're using whether this is a simple > change or not. > > regards, tom lane
Rainer Pruy wrote: > 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=12706loops=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. > Another approach might be to rewrite recursion into your hierarchy with the in 8.4 new WITH RECURSIVE option in sql queries. The possible gains there are way beyond anything you can accomplish with optimizing recursive functions. Regards, Yeb Havinga
On Mon, 1 Mar 2010, Rainer Pruy wrote: > It is a Java app, using jdbc, but through a proprietary persistence > framework. I'm just busy evaluating the effects on the app of > prohibiting prepared statements via jdbc. If this is not worthwhile, I'm > bound to some expensive reorganizations, sigh. You can disable the named statement by adding the parameter prepareThreshold=0 to your connection URL. Kris Jurka