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

Franck Routier <franck.routier@xxxxxxxxx> · Fri, 05 Apr 2013 15:55:08 +0200

Le 04/04/2013 21:08, Tom Lane a écrit :
Franck Routier <franck.routier@xxxxxxxxx> 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).

Regards,

Franck

Attachment:
smime.p7s

Description: Signature cryptographique S/MIME