pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedTrying to track down weird query stalls
19+ messages / 5 participants
[nested] [flat]
* Trying to track down weird query stalls
@ 2009-03-30 17:50 dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 17:50 UTC (permalink / raw)
To: pgsql-performance
I'm running a 64-bit build of Postgres 8.3.5 on AIX 5.3, and have a really
strange, annoying transient problem with one particular query stalling.
The symptom here is that when this query is made with X or more records in
a temp table involved in the join (where X is constant when the problem
manifests, but is different between manifestations) the query takes about
20 minutes. When the query is made with X-1 records it takes less than a
second. It's just this one query -- for everything else the system's nice
and snappy. The machine load's never above 9 (it's a 32 CPU box) and
hasn't had less than 60G of free system memory on it.
An EXPLAIN ANALYZE of the two queries (with X-1 and X records) is even
more bizarre. Not only are the two query plans identical (save trivial
differences because of the record count differences) but the explain
EXPLAIN ANALYZE total runtimes are near-identical -- the fast case showed
259ms, the slow case 265ms.
When the slow query was actually run, though, it took 20 minutes. There
were no blocked back ends shown in pg_stat_activity, and the back end
itself was definitely moving. I trussed the back end stuck running the
slow query and it spent nearly all its time doing kread() and kwrite()
calls. The DB log didn't show anything interesting in it. I checked to
make sure the SQL statement that was EXPLAIN ANALYZEd was the one actually
executed, and I pulled the client code into the debugger and
single-stepped through just to make sure it was getting stuck on that one
SQL statement and it wasn't the client doing something unexpected.
Just to be even more annoying, the problem goes away. Right now I can't
trigger the problem. Last friday it happened reliably feeding 58 records
into this query. The week before it was 38 records. Today? Nothing, the
system's full of snappy.
At the moment I'm at a loss as to what's going wrong, and the fact that I
can't duplicate it right now when I actually have time to look into the
problem's damned annoying. What I'm looking for are some hints as to where
to look the next time it does happen, or things I can flip on to catch
more in the log. (The logging parameters are all set at their defaults)
I'm going to try attaching with dbx to get a stack trace (I assume this is
relatively safe?) but past that I'm kind of stumped.
Help?
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 18:31 Robert Haas <robertmhaas@gmail.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Robert Haas @ 2009-03-30 18:31 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: pgsql-performance
On Mon, Mar 30, 2009 at 1:50 PM, <dan@sidhe.org> wrote:
> I'm running a 64-bit build of Postgres 8.3.5 on AIX 5.3, and have a really
> strange, annoying transient problem with one particular query stalling.
>
> The symptom here is that when this query is made with X or more records in
> a temp table involved in the join (where X is constant when the problem
> manifests, but is different between manifestations) the query takes about
> 20 minutes. When the query is made with X-1 records it takes less than a
> second. It's just this one query -- for everything else the system's nice
> and snappy. The machine load's never above 9 (it's a 32 CPU box) and
> hasn't had less than 60G of free system memory on it.
>
> An EXPLAIN ANALYZE of the two queries (with X-1 and X records) is even
> more bizarre. Not only are the two query plans identical (save trivial
> differences because of the record count differences) but the explain
> EXPLAIN ANALYZE total runtimes are near-identical -- the fast case showed
> 259ms, the slow case 265ms.
>
> When the slow query was actually run, though, it took 20 minutes. There
> were no blocked back ends shown in pg_stat_activity, and the back end
> itself was definitely moving. I trussed the back end stuck running the
> slow query and it spent nearly all its time doing kread() and kwrite()
> calls. The DB log didn't show anything interesting in it. I checked to
> make sure the SQL statement that was EXPLAIN ANALYZEd was the one actually
> executed, and I pulled the client code into the debugger and
> single-stepped through just to make sure it was getting stuck on that one
> SQL statement and it wasn't the client doing something unexpected.
>
> Just to be even more annoying, the problem goes away. Right now I can't
> trigger the problem. Last friday it happened reliably feeding 58 records
> into this query. The week before it was 38 records. Today? Nothing, the
> system's full of snappy.
>
> At the moment I'm at a loss as to what's going wrong, and the fact that I
> can't duplicate it right now when I actually have time to look into the
> problem's damned annoying. What I'm looking for are some hints as to where
> to look the next time it does happen, or things I can flip on to catch
> more in the log. (The logging parameters are all set at their defaults)
> I'm going to try attaching with dbx to get a stack trace (I assume this is
> relatively safe?) but past that I'm kind of stumped.
log_min_duration_statement is a good place to start, but it sounds
like the query plan you're getting when you test it by hand isn't the
same one that's actually executing, so I'm not sure how far that's
going to get you. contrib/auto_explain sounds like it would be just
the thing, but unfortunately that's an 8.4 feature which hasn't been
released yet. I'm not sure whether it could be built and run against
8.3.
...Robert
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 18:42 dan@sidhe.org
parent: Robert Haas <robertmhaas@gmail.com>
0 siblings, 2 replies; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 18:42 UTC (permalink / raw)
To: Robert Haas <robertmhaas@gmail.com>; +Cc: dan@sidhe.org; pgsql-performance
> On Mon, Mar 30, 2009 at 1:50 PM, <dan@sidhe.org> wrote:
>> I'm running a 64-bit build of Postgres 8.3.5 on AIX 5.3, and have a
>> really
>> strange, annoying transient problem with one particular query stalling.
>>
>> The symptom here is that when this query is made with X or more records
>> in
>> a temp table involved in the join (where X is constant when the problem
>> manifests, but is different between manifestations) the query takes
>> about
>> 20 minutes. When the query is made with X-1 records it takes less than a
>> second. It's just this one query -- for everything else the system's
>> nice
>> and snappy. The machine load's never above 9 (it's a 32 CPU box) and
>> hasn't had less than 60G of free system memory on it.
>>
>> An EXPLAIN ANALYZE of the two queries (with X-1 and X records) is even
>> more bizarre. Not only are the two query plans identical (save trivial
>> differences because of the record count differences) but the explain
>> EXPLAIN ANALYZE total runtimes are near-identical -- the fast case
>> showed
>> 259ms, the slow case 265ms.
>
> log_min_duration_statement is a good place to start, but it sounds
> like the query plan you're getting when you test it by hand isn't the
> same one that's actually executing, so I'm not sure how far that's
> going to get you. contrib/auto_explain sounds like it would be just
> the thing, but unfortunately that's an 8.4 feature which hasn't been
> released yet. I'm not sure whether it could be built and run against
> 8.3.
I'm not executing any of the EXPLAINs by hand, because I didn't want to
have to worry about typos or filling in temp tables with test data. Inside
the app the SQL for the problematic query's stored in a variable -- when
the task runs with debugging enabled it first executes the query with
EXPLAIN ANALYZE prepended and dumps the output, then it executes the query
itself. It's possible something's going wrong in that, but the code's
pretty simple.
Arguably in this case the actual query should run faster than the EXPLAIN
ANALYZE version, since the cache is hot. (Though that'd only likely shave
a few dozen ms off the runtime)
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 19:20 Robert Haas <robertmhaas@gmail.com>
parent: dan@sidhe.org
1 sibling, 1 reply; 19+ messages in thread
From: Robert Haas @ 2009-03-30 19:20 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: pgsql-performance
On Mon, Mar 30, 2009 at 2:42 PM, <dan@sidhe.org> wrote:
>> On Mon, Mar 30, 2009 at 1:50 PM, <dan@sidhe.org> wrote:
>>> I'm running a 64-bit build of Postgres 8.3.5 on AIX 5.3, and have a
>>> really
>>> strange, annoying transient problem with one particular query stalling.
>>>
>>> The symptom here is that when this query is made with X or more records
>>> in
>>> a temp table involved in the join (where X is constant when the problem
>>> manifests, but is different between manifestations) the query takes
>>> about
>>> 20 minutes. When the query is made with X-1 records it takes less than a
>>> second. It's just this one query -- for everything else the system's
>>> nice
>>> and snappy. The machine load's never above 9 (it's a 32 CPU box) and
>>> hasn't had less than 60G of free system memory on it.
>>>
>>> An EXPLAIN ANALYZE of the two queries (with X-1 and X records) is even
>>> more bizarre. Not only are the two query plans identical (save trivial
>>> differences because of the record count differences) but the explain
>>> EXPLAIN ANALYZE total runtimes are near-identical -- the fast case
>>> showed
>>> 259ms, the slow case 265ms.
>>
>> log_min_duration_statement is a good place to start, but it sounds
>> like the query plan you're getting when you test it by hand isn't the
>> same one that's actually executing, so I'm not sure how far that's
>> going to get you. contrib/auto_explain sounds like it would be just
>> the thing, but unfortunately that's an 8.4 feature which hasn't been
>> released yet. I'm not sure whether it could be built and run against
>> 8.3.
>
> I'm not executing any of the EXPLAINs by hand, because I didn't want to
> have to worry about typos or filling in temp tables with test data. Inside
> the app the SQL for the problematic query's stored in a variable -- when
> the task runs with debugging enabled it first executes the query with
> EXPLAIN ANALYZE prepended and dumps the output, then it executes the query
> itself. It's possible something's going wrong in that, but the code's
> pretty simple.
>
> Arguably in this case the actual query should run faster than the EXPLAIN
> ANALYZE version, since the cache is hot. (Though that'd only likely shave
> a few dozen ms off the runtime)
Well... yeah. Also EXPLAIN ANALYZE has a non-trivial amount of
overhead, so that is quite bizarre. I have to suspect there is some
subtle difference between the way the EXPLAIN ANALYZE is done and the
way the actual query is done... like maybe one uses parameter
substitution and the other doesn't or, well, I don't know. But I
don't see how turning on debugging (which is essentially what EXPLAIN
ANALYZE is) can prevent the query from being slow.
...Robert
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 19:35 dan@sidhe.org
parent: Robert Haas <robertmhaas@gmail.com>
0 siblings, 0 replies; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 19:35 UTC (permalink / raw)
To: Robert Haas <robertmhaas@gmail.com>; +Cc: pgsql-performance
> On Mon, Mar 30, 2009 at 2:42 PM, <dan@sidhe.org> wrote:
>>> On Mon, Mar 30, 2009 at 1:50 PM, <dan@sidhe.org> wrote:
>> I'm not executing any of the EXPLAINs by hand, because I didn't want to
>> have to worry about typos or filling in temp tables with test data.
>> Inside
>> the app the SQL for the problematic query's stored in a variable -- when
>> the task runs with debugging enabled it first executes the query with
>> EXPLAIN ANALYZE prepended and dumps the output, then it executes the
>> query
>> itself. It's possible something's going wrong in that, but the code's
>> pretty simple.
>>
>> Arguably in this case the actual query should run faster than the
>> EXPLAIN
>> ANALYZE version, since the cache is hot. (Though that'd only likely
>> shave
>> a few dozen ms off the runtime)
>
> Well... yeah. Also EXPLAIN ANALYZE has a non-trivial amount of
> overhead, so that is quite bizarre. I have to suspect there is some
> subtle difference between the way the EXPLAIN ANALYZE is done and the
> way the actual query is done... like maybe one uses parameter
> substitution and the other doesn't or, well, I don't know. But I
> don't see how turning on debugging (which is essentially what EXPLAIN
> ANALYZE is) can prevent the query from being slow.
Hence the query to the list. *Something* is going on, and beats me what.
I'm assuming I'm triggering some bug in the postgres back end, or there's
some completely bizarre edge case that this tickles. (The massive
kread/kwrite activity that truss showed me when I checked seemed rather
unusual, to say the least)
EXPLAIN ANALYZE is my normal means of diagnosing performance problems, but
that isn't helping as it shows perfectly sane results. That leaves
abnormal means, and outside of trussing the back end or attaching with dbx
to get a stack trace I just don't have any of those. I'm not even sure
what I should be looking for when I do get a stack trace.
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 19:38 Scott Marlowe <scott.marlowe@gmail.com>
parent: dan@sidhe.org
1 sibling, 1 reply; 19+ messages in thread
From: Scott Marlowe @ 2009-03-30 19:38 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; pgsql-performance
On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>> On Mon, Mar 30, 2009 at 1:50 PM, <dan@sidhe.org> wrote:
>>> I'm running a 64-bit build of Postgres 8.3.5 on AIX 5.3, and have a
>>> really
>>> strange, annoying transient problem with one particular query stalling.
>>>
>>> The symptom here is that when this query is made with X or more records
>>> in
>>> a temp table involved in the join (where X is constant when the problem
>>> manifests, but is different between manifestations) the query takes
>>> about
>>> 20 minutes. When the query is made with X-1 records it takes less than a
>>> second. It's just this one query -- for everything else the system's
>>> nice
>>> and snappy. The machine load's never above 9 (it's a 32 CPU box) and
>>> hasn't had less than 60G of free system memory on it.
>>>
>>> An EXPLAIN ANALYZE of the two queries (with X-1 and X records) is even
>>> more bizarre. Not only are the two query plans identical (save trivial
>>> differences because of the record count differences) but the explain
>>> EXPLAIN ANALYZE total runtimes are near-identical -- the fast case
>>> showed
>>> 259ms, the slow case 265ms.
>>
>> log_min_duration_statement is a good place to start, but it sounds
>> like the query plan you're getting when you test it by hand isn't the
>> same one that's actually executing, so I'm not sure how far that's
>> going to get you. contrib/auto_explain sounds like it would be just
>> the thing, but unfortunately that's an 8.4 feature which hasn't been
>> released yet. I'm not sure whether it could be built and run against
>> 8.3.
>
> I'm not executing any of the EXPLAINs by hand, because I didn't want to
> have to worry about typos or filling in temp tables with test data. Inside
> the app the SQL for the problematic query's stored in a variable -- when
> the task runs with debugging enabled it first executes the query with
> EXPLAIN ANALYZE prepended and dumps the output, then it executes the query
> itself. It's possible something's going wrong in that, but the code's
> pretty simple.
>
> Arguably in this case the actual query should run faster than the EXPLAIN
> ANALYZE version, since the cache is hot. (Though that'd only likely shave
> a few dozen ms off the runtime)
Joining a lot of tables together? Could be GEQO kicking in.
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 19:42 dan@sidhe.org
parent: Scott Marlowe <scott.marlowe@gmail.com>
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 19:42 UTC (permalink / raw)
To: Scott Marlowe <scott.marlowe@gmail.com>; +Cc: Robert Haas <robertmhaas@gmail.com>; pgsql-performance
> On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>> Arguably in this case the actual query should run faster than the
>> EXPLAIN
>> ANALYZE version, since the cache is hot. (Though that'd only likely
>> shave
>> a few dozen ms off the runtime)
>
> Joining a lot of tables together? Could be GEQO kicking in.
Only if I get different query plans for the query depending on whether
it's being EXPLAIN ANALYZEd or not. That seems unlikely...
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 19:47 Scott Marlowe <scott.marlowe@gmail.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Scott Marlowe @ 2009-03-30 19:47 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; pgsql-performance
On Mon, Mar 30, 2009 at 1:42 PM, <dan@sidhe.org> wrote:
>> On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>>> Arguably in this case the actual query should run faster than the
>>> EXPLAIN
>>> ANALYZE version, since the cache is hot. (Though that'd only likely
>>> shave
>>> a few dozen ms off the runtime)
>>
>> Joining a lot of tables together? Could be GEQO kicking in.
>
> Only if I get different query plans for the query depending on whether
> it's being EXPLAIN ANALYZEd or not. That seems unlikely...
Yes, you can. In fact you often will. Not because it's being
explained or not, just because that's how GEQO works.
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 20:02 dan@sidhe.org
parent: Scott Marlowe <scott.marlowe@gmail.com>
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 20:02 UTC (permalink / raw)
To: Scott Marlowe <scott.marlowe@gmail.com>; +Cc: dan@sidhe.org,"Robert Haas" <robertmhaas@gmail.com>; pgsql-performance
> On Mon, Mar 30, 2009 at 1:42 PM, <dan@sidhe.org> wrote:
>>> On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>>>> Arguably in this case the actual query should run faster than the
>>>> EXPLAIN
>>>> ANALYZE version, since the cache is hot. (Though that'd only likely
>>>> shave
>>>> a few dozen ms off the runtime)
>>>
>>> Joining a lot of tables together? Could be GEQO kicking in.
>>
>> Only if I get different query plans for the query depending on whether
>> it's being EXPLAIN ANALYZEd or not. That seems unlikely...
>
> Yes, you can. In fact you often will. Not because it's being
> explained or not, just because that's how GEQO works.
Ouch. I did *not* know that was possible -- I assumed that the plan was
deterministic and independent of explain analyze. The query has seven
tables (one of them a temp table) and my geqo_threshold is set to 12. If
I'm reading the docs right GEQO shouldn't kick in.
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 20:13 Robert Haas <robertmhaas@gmail.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Robert Haas @ 2009-03-30 20:13 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
On Mon, Mar 30, 2009 at 4:02 PM, <dan@sidhe.org> wrote:
>> On Mon, Mar 30, 2009 at 1:42 PM, <dan@sidhe.org> wrote:
>>>> On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>>>>> Arguably in this case the actual query should run faster than the
>>>>> EXPLAIN
>>>>> ANALYZE version, since the cache is hot. (Though that'd only likely
>>>>> shave
>>>>> a few dozen ms off the runtime)
>>>>
>>>> Joining a lot of tables together? Could be GEQO kicking in.
>>>
>>> Only if I get different query plans for the query depending on whether
>>> it's being EXPLAIN ANALYZEd or not. That seems unlikely...
>>
>> Yes, you can. In fact you often will. Not because it's being
>> explained or not, just because that's how GEQO works.
>
> Ouch. I did *not* know that was possible -- I assumed that the plan was
> deterministic and independent of explain analyze. The query has seven
> tables (one of them a temp table) and my geqo_threshold is set to 12. If
> I'm reading the docs right GEQO shouldn't kick in.
Any chance we could see the actual query? Right now I think we are
shooting in the dark.
...Robert
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 20:33 dan@sidhe.org
parent: Robert Haas <robertmhaas@gmail.com>
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 20:33 UTC (permalink / raw)
To: Robert Haas <robertmhaas@gmail.com>; +Cc: dan@sidhe.org,"Scott Marlowe" <scott.marlowe@gmail.com>; pgsql-performance
> On Mon, Mar 30, 2009 at 4:02 PM, <dan@sidhe.org> wrote:
>>> On Mon, Mar 30, 2009 at 1:42 PM, <dan@sidhe.org> wrote:
>>>>> On Mon, Mar 30, 2009 at 12:42 PM, <dan@sidhe.org> wrote:
>>>>>> Arguably in this case the actual query should run faster than the
>>>>>> EXPLAIN
>>>>>> ANALYZE version, since the cache is hot. (Though that'd only likely
>>>>>> shave
>>>>>> a few dozen ms off the runtime)
>>>>>
>>>>> Joining a lot of tables together? Could be GEQO kicking in.
>>>>
>>>> Only if I get different query plans for the query depending on whether
>>>> it's being EXPLAIN ANALYZEd or not. That seems unlikely...
>>>
>>> Yes, you can. In fact you often will. Not because it's being
>>> explained or not, just because that's how GEQO works.
>>
>> Ouch. I did *not* know that was possible -- I assumed that the plan was
>> deterministic and independent of explain analyze. The query has seven
>> tables (one of them a temp table) and my geqo_threshold is set to 12. If
>> I'm reading the docs right GEQO shouldn't kick in.
>
> Any chance we could see the actual query? Right now I think we are
> shooting in the dark.
The query is:
select distinct
temp_symbol.entityid,
temp_symbol.libname,
temp_symbol.objid,
temp_symbol.objname,
temp_symbol.fromsymid,
temp_symbol.fromsymtype,
temp_symbol.objinstance,
NULL,
temp_symbol.csid,
libinstance.entityid,
NULL,
libobject.objid,
NULL,
provide_symbol.symbolid,
provide_symbol.symboltype,
libobject.objinstance,
libobject.libinstanceid,
objectinstance.csid,
NULL,
provide_symbol.is_weak,
NULL,
provide_symbol.is_local,
NULL,
provide_symbol.is_template,
NULL,
provide_symbol.is_common
from libinstance,
library,
libobject,
provide_symbol,
temp_symbol,
objectinstance,
attributes
where libinstance.libdate <= 1238445044
and libinstance.enddate > 1238445044
and libinstance.libinstanceid = libobject.libinstanceid
and libinstance.architecture = ?
and attributes.entityid = libinstance.entityid
and attributes.branchid = libinstance.branchid
and attributes.architecture = libinstance.architecture
and library.libid = libinstance.libid
and not secondary
and attribute in ('notoffline', 'notoffline')
and (provide_symbol.symboltype = 'T')
and libobject.objinstance = provide_symbol.objinstance
and libinstance.branchid = ?
and provide_symbol.symbolid = temp_symbol.symbolid
and objectinstance.objinstance = libobject.objinstance
and libinstance.istemp = 0
The explain analyze for the query's attached in a (possibly hopeless)
attempt to keep it from being word-wrapped into unreadability.
-Dan
Attachments:
slowquery.txt (text/plain, 5.6K) download
Unique (cost=25323267.82..25350114.59 rows=397730 width=192) (actual time=277.963..278.054 rows=35 loops=1)
-> Sort (cost=25323267.82..25324262.14 rows=397730 width=192) (actual time=277.960..277.967 rows=35 loops=1)
Sort Key: temp_symbol.entityid, temp_symbol.libname, temp_symbol.objid, temp_symbol.objname, temp_symbol.fromsymid, temp_symbol.fromsymtype, temp_symbol.objinstance, temp_symbol.csid, libinstance.ent
ityid, libobject.objid, provide_symbol.symbolid, libobject.objinstance, libobject.libinstanceid, objectinstance.csid, provide_symbol.is_weak, provide_symbol.is_local, provide_symbol.is_template, provide_symb
ol.is_common
Sort Method: quicksort Memory: 27kB
-> Merge Join (cost=25234932.60..25286276.09 rows=397730 width=192) (actual time=276.217..277.397 rows=35 loops=1)
Merge Cond: (libinstance.libinstanceid = libobject.libinstanceid)
-> Sort (cost=7950.07..7958.88 rows=3523 width=8) (actual time=256.190..256.655 rows=1838 loops=1)
Sort Key: libinstance.libinstanceid
Sort Method: quicksort Memory: 135kB
-> Merge Join (cost=7604.97..7742.52 rows=3523 width=8) (actual time=231.880..252.275 rows=1838 loops=1)
Merge Cond: (libinstance.libid = library.libid)
-> Sort (cost=5951.50..5960.32 rows=3529 width=12) (actual time=156.866..157.638 rows=1849 loops=1)
Sort Key: libinstance.libid
Sort Method: quicksort Memory: 135kB
-> Merge Join (cost=5657.33..5743.55 rows=3529 width=12) (actual time=141.311..152.022 rows=1849 loops=1)
Merge Cond: (libinstance.entityid = attributes.entityid)
-> Sort (cost=4143.42..4159.22 rows=6319 width=18) (actual time=126.355..128.805 rows=5532 loops=1)
Sort Key: libinstance.entityid
Sort Method: quicksort Memory: 625kB
-> Seq Scan on libinstance (cost=0.00..3744.52 rows=6319 width=18) (actual time=0.074..107.409 rows=5533 loops=1)
Filter: ((libdate <= 1238186855) AND (enddate > 1238186855) AND (architecture = 1::smallint) AND (branchid = 0) AND (istemp = 0))
-> Sort (cost=1513.91..1523.58 rows=3867 width=12) (actual time=14.936..15.698 rows=1999 loops=1)
Sort Key: attributes.entityid
Sort Method: quicksort Memory: 142kB
-> Bitmap Heap Scan on attributes (cost=129.82..1283.50 rows=3867 width=12) (actual time=4.447..10.207 rows=1985 loops=1)
Recheck Cond: ((attribute = ANY ('{notoffline,notoffline}'::text[])) AND (branchid = 0) AND (architecture = 1::smallint))
-> Bitmap Index Scan on attributeindex3 (cost=0.00..128.86 rows=3867 width=0) (actual time=4.206..4.206 rows=3970 loops=1)
Index Cond: ((attribute = ANY ('{notoffline,notoffline}'::text[])) AND (branchid = 0) AND (architecture = 1::smallint))
-> Sort (cost=1653.46..1695.81 rows=16939 width=4) (actual time=74.998..80.969 rows=16958 loops=1)
Sort Key: library.libid
Sort Method: quicksort Memory: 1564kB
-> Seq Scan on library (cost=0.00..463.66 rows=16939 width=4) (actual time=0.024..23.808 rows=16968 loops=1)
Filter: (NOT secondary)
-> Materialize (cost=25226982.52..25346796.41 rows=9585111 width=188) (actual time=19.157..19.625 rows=490 loops=1)
-> Sort (cost=25226982.52..25250945.30 rows=9585111 width=188) (actual time=19.149..19.257 rows=490 loops=1)
Sort Key: libobject.libinstanceid
Sort Method: quicksort Memory: 64kB
-> Nested Loop (cost=0.00..23230910.12 rows=9585111 width=188) (actual time=0.236..18.276 rows=501 loops=1)
-> Nested Loop (cost=0.00..92332.83 rows=9981 width=184) (actual time=0.172..10.657 rows=509 loops=1)
-> Nested Loop (cost=0.00..41179.30 rows=9981 width=162) (actual time=0.117..4.166 rows=509 loops=1)
-> Seq Scan on temp_symbol (cost=0.00..2.52 rows=52 width=148) (actual time=0.025..0.062 rows=52 loops=1)
-> Index Scan using provsymbolindex1 on provide_symbol (cost=0.00..789.46 rows=192 width=18) (actual time=0.027..0.066 rows=10 loops=52)
Index Cond: ((provide_symbol.symbolid = temp_symbol.symbolid) AND (provide_symbol.symboltype = 'T'::bpchar))
-> Index Scan using objectinstance_pkey on objectinstance (cost=0.00..5.11 rows=1 width=22) (actual time=0.010..0.011 rows=1 loops=509)
Index Cond: (objectinstance.objinstance = provide_symbol.objinstance)
-> Index Scan using libobjindex2 on libobject (cost=0.00..2306.21 rows=964 width=12) (actual time=0.012..0.013 rows=1 loops=509)
Index Cond: (libobject.objinstance = provide_symbol.objinstance)
* Re: Trying to track down weird query stalls
@ 2009-03-30 20:39 Alvaro Herrera <alvherre@commandprompt.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Alvaro Herrera @ 2009-03-30 20:39 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
dan@sidhe.org escribió:
> where libinstance.libdate <= 1238445044
> and libinstance.enddate > 1238445044
> and libinstance.libinstanceid = libobject.libinstanceid
> and libinstance.architecture = ?
How are you generating the explain? My bet is that you're just
substituting a literal in the architecture condition, but if the driver
is smart then maybe it's preparating the query beforehand. You'll get a
different plan in that case. Try something like this:
prepare foo(smallint) as ...
where libinstance.architecture = $1
...
explain analyze execute foo(1);
If the plan you get from that is bad (and it often is), you should look
at avoiding a query prepare.
--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 20:49 dan@sidhe.org
parent: Alvaro Herrera <alvherre@commandprompt.com>
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 20:49 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: dan@sidhe.org,"Robert Haas" <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
> dan@sidhe.org escribió:
>
>> where libinstance.libdate <= 1238445044
>> and libinstance.enddate > 1238445044
>> and libinstance.libinstanceid = libobject.libinstanceid
>> and libinstance.architecture = ?
>
> How are you generating the explain? My bet is that you're just
> substituting a literal in the architecture condition, but if the driver
> is smart then maybe it's preparating the query beforehand. You'll get a
> different plan in that case.
I don't think so. Perl's DBI is involved, but the statement's in a
variable. The code in question is:
if ($db->{debug}) {
$db->debug("SQL is: $sql\n");
my $rows = $db->{dbh}->selectall_arrayref("explain analyze $sql",
undef, $db->{arch},
$db->{basebranch});
foreach my $row (@$rows) {
$db->debug(join(" ", @$row). "\n");
}
$db->debug_stamp("Initial query done\n");
}
$rows = $db->{dbh}->selectall_arrayref($sql,
undef, $db->{arch},
$db->{basebranch});
There's no transform of the sql variable between the two statements, just
a quick loop over the returned rows from the explain analyze to print them
out. (I did try to make sure that the debugging bits were done the same
way as the mainline code, but I may have bobbled something)
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:00 Alvaro Herrera <alvherre@commandprompt.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Alvaro Herrera @ 2009-03-30 21:00 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
dan@sidhe.org escribió:
> > dan@sidhe.org escribió:
> >
> >> where libinstance.libdate <= 1238445044
> >> and libinstance.enddate > 1238445044
> >> and libinstance.libinstanceid = libobject.libinstanceid
> >> and libinstance.architecture = ?
> >
> > How are you generating the explain? My bet is that you're just
> > substituting a literal in the architecture condition, but if the driver
> > is smart then maybe it's preparating the query beforehand. You'll get a
> > different plan in that case.
>
> I don't think so. Perl's DBI is involved, but the statement's in a
> variable.
So what's the "?" in the query you pasted earlier?
--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:07 dan@sidhe.org
parent: Alvaro Herrera <alvherre@commandprompt.com>
0 siblings, 1 reply; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 21:07 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: dan@sidhe.org,"Robert Haas" <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
> dan@sidhe.org escribió:
>> > dan@sidhe.org escribió:
>> >
>> >> where libinstance.libdate <= 1238445044
>> >> and libinstance.enddate > 1238445044
>> >> and libinstance.libinstanceid = libobject.libinstanceid
>> >> and libinstance.architecture = ?
>> >
>> > How are you generating the explain? My bet is that you're just
>> > substituting a literal in the architecture condition, but if the
>> driver
>> > is smart then maybe it's preparating the query beforehand. You'll get
>> a
>> > different plan in that case.
>>
>> I don't think so. Perl's DBI is involved, but the statement's in a
>> variable.
>
> So what's the "?" in the query you pasted earlier?
The first ? (for architecture) is 1, the second ? (for branchid) is 0.
They both should get passed to Postgres as $1 and $2, respectively,
assuming DBD::Pg does its substitution right. (They're both supposed to go
in as placeholders)
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:22 Alvaro Herrera <alvherre@commandprompt.com>
parent: dan@sidhe.org
0 siblings, 1 reply; 19+ messages in thread
From: Alvaro Herrera @ 2009-03-30 21:22 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
dan@sidhe.org escribió:
> > So what's the "?" in the query you pasted earlier?
>
> The first ? (for architecture) is 1, the second ? (for branchid) is 0.
> They both should get passed to Postgres as $1 and $2, respectively,
> assuming DBD::Pg does its substitution right. (They're both supposed to go
> in as placeholders)
Right, so how about you reread what I wrote above?
Oh, hmm, so to be more clear: I don't think DBD::Pg is actually sending
EXECUTE PREPARE. You need to do this over psql.
--
Alvaro Herrera http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:34 dan@sidhe.org
parent: Alvaro Herrera <alvherre@commandprompt.com>
0 siblings, 2 replies; 19+ messages in thread
From: dan@sidhe.org @ 2009-03-30 21:34 UTC (permalink / raw)
To: Alvaro Herrera <alvherre@commandprompt.com>; +Cc: dan@sidhe.org,"Robert Haas" <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
> dan@sidhe.org escribió:
>
>> > So what's the "?" in the query you pasted earlier?
>>
>> The first ? (for architecture) is 1, the second ? (for branchid) is 0.
>> They both should get passed to Postgres as $1 and $2, respectively,
>> assuming DBD::Pg does its substitution right. (They're both supposed to
>> go
>> in as placeholders)
>
> Right, so how about you reread what I wrote above?
>
> Oh, hmm, so to be more clear: I don't think DBD::Pg is actually sending
> EXECUTE PREPARE. You need to do this over psql.
Fair enough. (And sorry about the mis-read) Next time this occurs I'll try
and duplicate this in psql. FWIW, a quick read of the C underlying the
DBD::Pg module shows it using PQexecPrepared, so I'm pretty sure it is
using prepared statements with placeholders, but double-checking seems
prudent.
-Dan
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:38 Alvaro Herrera <alvherre@commandprompt.com>
parent: dan@sidhe.org
1 sibling, 0 replies; 19+ messages in thread
From: Alvaro Herrera @ 2009-03-30 21:38 UTC (permalink / raw)
To: dan@sidhe.org; +Cc: Robert Haas <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
dan@sidhe.org escribió:
> Fair enough. (And sorry about the mis-read) Next time this occurs I'll try
> and duplicate this in psql. FWIW, a quick read of the C underlying the
> DBD::Pg module shows it using PQexecPrepared, so I'm pretty sure it is
> using prepared statements with placeholders, but double-checking seems
> prudent.
Yes, but I doubt that it'll be smart enough to work for EXPLAIN in the
way we need here.
--
Alvaro Herrera http://www.CommandPrompt.com/
The PostgreSQL Company - Command Prompt, Inc.
^ permalink raw reply [nested|flat] 19+ messages in thread
* Re: Trying to track down weird query stalls
@ 2009-03-30 21:44 Scott Carey <scott@richrelevance.com>
parent: dan@sidhe.org
1 sibling, 0 replies; 19+ messages in thread
From: Scott Carey @ 2009-03-30 21:44 UTC (permalink / raw)
To: dan@sidhe.org <dan@sidhe.org>; Alvaro Herrera <alvherre@commandprompt.com>; +Cc: Robert Haas <robertmhaas@gmail.com>; Scott Marlowe <scott.marlowe@gmail.com>; pgsql-performance
On 3/30/09 2:34 PM, "dan@sidhe.org" <dan@sidhe.org> wrote:
>> dan@sidhe.org escribió:
>>
>>>> So what's the "?" in the query you pasted earlier?
>>>
>>> The first ? (for architecture) is 1, the second ? (for branchid) is 0.
>>> They both should get passed to Postgres as $1 and $2, respectively,
>>> assuming DBD::Pg does its substitution right. (They're both supposed to
>>> go
>>> in as placeholders)
>>
>> Right, so how about you reread what I wrote above?
>>
>> Oh, hmm, so to be more clear: I don't think DBD::Pg is actually sending
>> EXECUTE PREPARE. You need to do this over psql.
>
> Fair enough. (And sorry about the mis-read) Next time this occurs I'll try
> and duplicate this in psql. FWIW, a quick read of the C underlying the
> DBD::Pg module shows it using PQexecPrepared, so I'm pretty sure it is
> using prepared statements with placeholders, but double-checking seems
> prudent.
>
> -Dan
>
Regardless, its always a good idea to do a manual explain analyze with and
without parameterization in psql if prepared statements are involved. The
query planner functions very differently with and without them, almost
always with a performance detriment to query execution times when
parameterized.
^ permalink raw reply [nested|flat] 19+ messages in thread
end of thread, other threads:[~2009-03-30 21:44 UTC | newest]
Thread overview: 19+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2009-03-30 17:50 Trying to track down weird query stalls dan@sidhe.org
2009-03-30 18:31 ` Robert Haas <robertmhaas@gmail.com>
2009-03-30 18:42 ` dan@sidhe.org
2009-03-30 19:20 ` Robert Haas <robertmhaas@gmail.com>
2009-03-30 19:35 ` dan@sidhe.org
2009-03-30 19:38 ` Scott Marlowe <scott.marlowe@gmail.com>
2009-03-30 19:42 ` dan@sidhe.org
2009-03-30 19:47 ` Scott Marlowe <scott.marlowe@gmail.com>
2009-03-30 20:02 ` dan@sidhe.org
2009-03-30 20:13 ` Robert Haas <robertmhaas@gmail.com>
2009-03-30 20:33 ` dan@sidhe.org
2009-03-30 20:39 ` Alvaro Herrera <alvherre@commandprompt.com>
2009-03-30 20:49 ` dan@sidhe.org
2009-03-30 21:00 ` Alvaro Herrera <alvherre@commandprompt.com>
2009-03-30 21:07 ` dan@sidhe.org
2009-03-30 21:22 ` Alvaro Herrera <alvherre@commandprompt.com>
2009-03-30 21:34 ` dan@sidhe.org
2009-03-30 21:38 ` Alvaro Herrera <alvherre@commandprompt.com>
2009-03-30 21:44 ` Scott Carey <scott@richrelevance.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