Re: What happens between end of explain analyze and end of query execution ?

On Fri, Apr 5, 2013 at 8:55 AM, Franck Routier <franck(dot)routier(at)axege(dot)com> wrote:
> Le 04/04/2013 21:08, Tom Lane a écrit :
>
>> Franck Routier <franck(dot)routier(at)axege(dot)com> writes:
>>>
>>> The request is not using any function. It looks like this:
>>> [ unexciting query ]
>>
>> Hmph. Can't see any reason for that to take a remarkably long time to
>> plan. Can you put together a self-contained test case demonstrating
>> excessive planning time? What PG version is this, anyway?
>>
>> regards, tom lane
>>
>>
> Well, I don't know how to reproduce, as it is really only happening on this
> database.
>
> What I notice is that removing joins has a huge impact on the time explain
> takes to return:
>
> The full query takes 2.6 seconds to return. Notice it has dropped from 3.6
> seconds to 2.6 since yesterday after I did a vacuum analyze on the tables
> that go into the request.
>
> EXPLAIN SELECT *
>
> FROM sanrss
> LEFT JOIN sanrum ON sanrum.sanrum___rforefide =
> sanrss.sanrss___rforefide AND sanrum.sanrum___rfovsnide =
> sanrss.sanrss___rfovsnide AND sanrum.sanrum___sanrsside = sanrss.sanrsside
> LEFT JOIN sanact ON sanact.sanact___rforefide =
> sanrum.sanrum___rforefide AND sanact.sanact___rfovsnide =
> sanrum.sanrum___rfovsnide AND sanact.sanact___sanrsside =
> sanrum.sanrum___sanrsside AND sanact.sanact___sanrumide = sanrum.sanrumide
> AND sanact.sanact___sanrumide IS NOT NULL AND
> sanact.sanact___rsanopide='CCAM'
> LEFT JOIN sandia ON sandia.sandia___rforefide =
> sanrum.sanrum___rforefide AND sandia.sandia___rfovsnide =
> sanrum.sanrum___rfovsnide AND sandia.sandia___sanrsside =
> sanrum.sanrum___sanrsside AND sandia.sandia___sanrumide = sanrum.sanrumide
> AND sandia.sandiasig=1
> LEFT JOIN saneds ON sanrss.sanrss___rforefide =
> saneds.saneds___rforefide AND sanrss.sanrss___rfovsnide =
> saneds.saneds___rfovsnide AND sanrss.sanrss___sanedside = saneds.sanedside
> LEFT JOIN rsaidp ON saneds.saneds___rforefide =
> rsaidp.rsaidp___rforefide AND saneds.saneds___rsaidpide = rsaidp.rsaidpide
> WHERE sanrss.sanrss___rforefide = 'CHCL' AND
> sanrss.sanrss___rfovsnide = '201012_600' AND sanrss.sanrsside = '1188100'
> ORDER BY sanrum.sanrumord, sanrum.sanrumide
>
> ==> 2.6 seconds
>
> If I remove the join on either table 'sandia' or table 'saneds', the explain
> return in 1.2 seconds. If I remove both, explain returns in 48ms.
>
> EXPLAIN SELECT *
>
> FROM sanrss
> LEFT JOIN sanrum ON sanrum.sanrum___rforefide =
> sanrss.sanrss___rforefide AND sanrum.sanrum___rfovsnide =
> sanrss.sanrss___rfovsnide AND sanrum.sanrum___sanrsside = sanrss.sanrsside
> LEFT JOIN sanact ON sanact.sanact___rforefide =
> sanrum.sanrum___rforefide AND sanact.sanact___rfovsnide =
> sanrum.sanrum___rfovsnide AND sanact.sanact___sanrsside =
> sanrum.sanrum___sanrsside AND sanact.sanact___sanrumide = sanrum.sanrumide
> AND sanact.sanact___sanrumide IS NOT NULL AND
> sanact.sanact___rsanopide='CCAM'
> LEFT JOIN saneds ON sanrss.sanrss___rforefide =
> saneds.saneds___rforefide AND sanrss.sanrss___rfovsnide =
> saneds.saneds___rfovsnide AND sanrss.sanrss___sanedside = saneds.sanedside
> LEFT JOIN rsaidp ON saneds.saneds___rforefide =
> rsaidp.rsaidp___rforefide AND saneds.saneds___rsaidpide = rsaidp.rsaidpide
> WHERE sanrss.sanrss___rforefide = 'CHCL' AND
> sanrss.sanrss___rfovsnide = '201012_600' AND sanrss.sanrsside = '1188100'
> ORDER BY sanrum.sanrumord, sanrum.sanrumide
>
> ==> 1.2 seconds
>
> EXPLAIN SELECT *
>
> FROM sanrss
> LEFT JOIN sanrum ON sanrum.sanrum___rforefide =
> sanrss.sanrss___rforefide AND sanrum.sanrum___rfovsnide =
> sanrss.sanrss___rfovsnide AND sanrum.sanrum___sanrsside = sanrss.sanrsside
> LEFT JOIN sanact ON sanact.sanact___rforefide =
> sanrum.sanrum___rforefide AND sanact.sanact___rfovsnide =
> sanrum.sanrum___rfovsnide AND sanact.sanact___sanrsside =
> sanrum.sanrum___sanrsside AND sanact.sanact___sanrumide = sanrum.sanrumide
> AND sanact.sanact___sanrumide IS NOT NULL AND
> sanact.sanact___rsanopide='CCAM'
> LEFT JOIN sandia ON sandia.sandia___rforefide =
> sanrum.sanrum___rforefide AND sandia.sandia___rfovsnide =
> sanrum.sanrum___rfovsnide AND sandia.sandia___sanrsside =
> sanrum.sanrum___sanrsside AND sandia.sandia___sanrumide = sanrum.sanrumide
> AND sandia.sandiasig=1
> WHERE sanrss.sanrss___rforefide = 'CHCL' AND
> sanrss.sanrss___rfovsnide = '201012_600' AND sanrss.sanrsside = '1188100'
> ORDER BY sanrum.sanrumord, sanrum.sanrumide
>
> ==> 1.2 seconds
>
> EXPLAIN SELECT *
>
> FROM sanrss
> LEFT JOIN sanrum ON sanrum.sanrum___rforefide =
> sanrss.sanrss___rforefide AND sanrum.sanrum___rfovsnide =
> sanrss.sanrss___rfovsnide AND sanrum.sanrum___sanrsside = sanrss.sanrsside
> LEFT JOIN sanact ON sanact.sanact___rforefide =
> sanrum.sanrum___rforefide AND sanact.sanact___rfovsnide =
> sanrum.sanrum___rfovsnide AND sanact.sanact___sanrsside =
> sanrum.sanrum___sanrsside AND sanact.sanact___sanrumide = sanrum.sanrumide
> AND sanact.sanact___sanrumide IS NOT NULL AND
> sanact.sanact___rsanopide='CCAM'
> WHERE sanrss.sanrss___rforefide = 'CHCL' AND
> sanrss.sanrss___rfovsnide = '201012_600' AND sanrss.sanrsside = '1188100'
> ORDER BY sanrum.sanrumord, sanrum.sanrumide
>
> ==> 48 ms
>
> Maybe the statistics tables for sandia and saneds are in a bad shape ?
> (don't know how to check this).

Ok, "explain" (without analyze) is measuring plan time only (not
execution time). Can you confirm that's the time we are measuring
(and again, according to what)? Performance issues here are a
different ball game. Please supply precise version#, there were a
couple of plantime bugs fixed recently.

merlin