From: dan@sidhe.org
To: Robert Haas <robertmhaas@gmail.com>
Cc: dan@sidhe.org,"Scott Marlowe" <scott.marlowe@gmail.com>
Cc: pgsql-performance@postgresql.org
Subject: Re: Trying to track down weird query stalls
Date: Mon, 30 Mar 2009 16:33:14 -0400 (EDT)
Message-ID: <56504.199.172.169.35.1238445194.squirrel@localhost> (raw)
In-Reply-To: <603c8f070903301313u1a9606a3m27da187b5e376785@mail.gmail.com>
References: <58166.199.172.169.15.1238435452.squirrel@localhost>
<603c8f070903301131p8086067ob552d09e8b21c82@mail.gmail.com>
<56921.199.172.169.36.1238438533.squirrel@localhost>
<dcc563d10903301238u135d82bpf498c2d40ac31977@mail.gmail.com>
<57654.199.172.169.17.1238442145.squirrel@localhost>
<dcc563d10903301247t58bef7cbsd0b6d3bbd1a5e046@mail.gmail.com>
<56164.199.172.169.17.1238443348.squirrel@localhost>
<603c8f070903301313u1a9606a3m27da187b5e376785@mail.gmail.com>
> 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)
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: dan@sidhe.org, robertmhaas@gmail.com, scott.marlowe@gmail.com
Subject: Re: Trying to track down weird query stalls
In-Reply-To: <56504.199.172.169.35.1238445194.squirrel@localhost>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
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