pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedQuery slowing down significantly??
7+ messages / 4 participants
[nested] [flat]
* Query slowing down significantly??
@ 2010-03-01 12:50 Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 1 reply; 7+ messages in thread
From: Rainer Pruy @ 2010-03-01 12:50 UTC (permalink / raw)
To: 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.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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
@ 2010-03-01 16:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
0 siblings, 1 reply; 7+ messages in thread
From: Tom Lane @ 2010-03-01 16:15 UTC (permalink / raw)
To: Rainer Pruy <Rainer.Pruy@Acrys.COM>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
@ 2010-03-01 17:48 ` Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 18:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 19:34 ` Re: Query slowing down significantly?? Yeb Havinga <yebhavinga@gmail.com>
0 siblings, 2 replies; 7+ messages in thread
From: Rainer Pruy @ 2010-03-01 17:48 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
@ 2010-03-01 18:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 18:49 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
1 sibling, 1 reply; 7+ messages in thread
From: Tom Lane @ 2010-03-01 18:15 UTC (permalink / raw)
To: Rainer Pruy <Rainer.Pruy@Acrys.COM>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 18:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
@ 2010-03-01 18:49 ` Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-02 22:46 ` Re: Query slowing down significantly?? Kris Jurka <books@ejurka.com>
0 siblings, 1 reply; 7+ messages in thread
From: Rainer Pruy @ 2010-03-01 18:49 UTC (permalink / raw)
To: Tom Lane <tgl@sss.pgh.pa.us>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 18:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 18:49 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
@ 2010-03-02 22:46 ` Kris Jurka <books@ejurka.com>
0 siblings, 0 replies; 7+ messages in thread
From: Kris Jurka @ 2010-03-02 22:46 UTC (permalink / raw)
To: Rainer Pruy <Rainer.Pruy@Acrys.COM>; +Cc: Tom Lane <tgl@sss.pgh.pa.us>; pgsql-performance
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
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: Query slowing down significantly??
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Re: Query slowing down significantly?? Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Re: Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
@ 2010-03-01 19:34 ` Yeb Havinga <yebhavinga@gmail.com>
1 sibling, 0 replies; 7+ messages in thread
From: Yeb Havinga @ 2010-03-01 19:34 UTC (permalink / raw)
To: Rainer Pruy <Rainer.Pruy@Acrys.COM>; +Cc: pgsql-performance
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=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.
>
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
^ permalink raw reply [nested|flat] 7+ messages in thread
end of thread, other threads:[~2010-03-02 22:46 UTC | newest]
Thread overview: 7+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2010-03-01 12:50 Query slowing down significantly?? Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 16:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 17:48 ` Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-01 18:15 ` Tom Lane <tgl@sss.pgh.pa.us>
2010-03-01 18:49 ` Rainer Pruy <Rainer.Pruy@Acrys.COM>
2010-03-02 22:46 ` Kris Jurka <books@ejurka.com>
2010-03-01 19:34 ` Yeb Havinga <yebhavinga@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox