Обсуждение: Query slowing down significantly??

От:
Rainer Pruy
Дата:

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

От:
Tom Lane
Дата:

Rainer Pruy <> 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
Дата:

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


От:
Tom Lane
Дата:

Rainer Pruy <> 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
Дата:

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

От:
Yeb Havinga
Дата:

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


От:
Kris Jurka
Дата:


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