Message-ID: <515D9FC5.7030105@axege.com>
Date: Thu, 04 Apr 2013 17:44:05 +0200
From: Franck Routier <franck.routier@axege.com>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:17.0) Gecko/20130311 Thunderbird/17.0.4
MIME-Version: 1.0
To: Nikolas Everett <nik9000@gmail.com>
CC: postgres performance list <pgsql-performance@postgresql.org>
Subject: Re: What happens between end of explain analyze and end
	of query execution ?
References: <515D92BF.5000309@axege.com>
	<CAPmjWd100eemBz1RTw=r24zgh8+YO8iq86fThqsALznrPuyWqg@mail.gmail.com>
In-Reply-To: 
 <CAPmjWd100eemBz1RTw=r24zgh8+YO8iq86fThqsALznrPuyWqg@mail.gmail.com>
Content-Type: multipart/signed; protocol="application/pkcs7-signature";
	micalg=sha1; boundary="------------ms020903030307010309020208"
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Ceci est un message signé cryptographiquement au format MIME.

--------------ms020903030307010309020208
Content-Type: multipart/alternative;
 boundary="------------070803090408090807090001"

This is a multi-part message in MIME format.
--------------070803090408090807090001
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: quoted-printable

Right, explain alone takes 3.6 seconds, so the time really seems to go=20
query planning...


Le 04/04/2013 17:01, Nikolas Everett a =E9crit :
> We had a problem where the actual query planning time blew up and took =

> way more time then the query execution.  We reproduced the problem by=20
> forming a new connection and then just explaining the query.  If that=20
> takes more than a couple of milliseconds you likely have the problem.=20
>  The second plan was fast.
>
> We then dtraced the backend process for a new connection and found=20
> that opening files had become super slow.  In our case this was caused =

> by running the database on nfs.
>
> Good luck,
>
> Nik
>
>
> On Thu, Apr 4, 2013 at 10:48 AM, Franck Routier=20
> <franck.routier@axege.com <mailto:franck.routier@axege.com>> wrote:
>
>     Hi,
>
>     I have query that should be quick, and used to be quick, but is
>     not anymore... Explain analyze can be seen here
>     http://explain.depesz.com/s/cpV
>     but it is fundamentaly quick : Total runtime: 0.545 ms.
>
>     But query execution takes 3.6 seconds. Only 12 rows are returned.
>     Adding a limit 1 has no influence.
>
>     Postgresql client and server are on the same server, on localhost.
>
>     I wonder where my 3.5 seconds are going....
>
>     Notice that there is no fancy configuration to tell Postgresql to
>     evaluate every query plan on earth, that is gecoxxxx settings are
>     on their default values.
>
>     Any idea on what can be happening that takes so long ?
>
>     Franck
>
>


--------------070803090408090807090001
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

<html>
  <head>
    <meta content=3D"text/html; charset=3DISO-8859-1"
      http-equiv=3D"Content-Type">
  </head>
  <body bgcolor=3D"#FFFFFF" text=3D"#000000">
    <div class=3D"moz-cite-prefix">Right, explain alone takes 3.6 seconds=
,
      so the time really seems to go query planning...<br>
      <br>
      <br>
      Le 04/04/2013 17:01, Nikolas Everett a &eacute;crit&nbsp;:<br>
    </div>
    <blockquote
cite=3D"mid:CAPmjWd100eemBz1RTw=3Dr24zgh8+YO8iq86fThqsALznrPuyWqg@mail.gm=
ail.com"
      type=3D"cite">
      <div dir=3D"ltr">We had a problem where the actual query planning
        time blew up and took way more time then the query execution.
        &nbsp;We reproduced the problem by forming a new connection and t=
hen
        just explaining the query. &nbsp;If that takes more than a couple=
 of
        milliseconds you likely have the problem. &nbsp;The second plan w=
as
        fast.
        <div>
          <br>
        </div>
        <div style=3D"">We then dtraced the backend process for a new
          connection and found that opening files had become super slow.
          &nbsp;In our case this was caused by running the database on nf=
s.</div>
        <div style=3D""><br>
        </div>
        <div style=3D"">
          Good luck,</div>
        <div style=3D""><br>
        </div>
        <div style=3D"">Nik</div>
      </div>
      <div class=3D"gmail_extra"><br>
        <br>
        <div class=3D"gmail_quote">On Thu, Apr 4, 2013 at 10:48 AM, Franc=
k
          Routier <span dir=3D"ltr">&lt;<a moz-do-not-send=3D"true"
              href=3D"mailto:franck.routier@axege.com" target=3D"_blank">=
franck.routier@axege.com</a>&gt;</span>
          wrote:<br>
          <blockquote class=3D"gmail_quote" style=3D"margin:0 0 0
            .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
            <br>
            I have query that should be quick, and used to be quick, but
            is not anymore... Explain analyze can be seen here <a
              moz-do-not-send=3D"true"
              href=3D"http://explain.depesz.com/s/cpV" target=3D"_blank">=
http://explain.depesz.com/s/cpV</a><br>
            but it is fundamentaly quick : Total runtime: 0.545 ms.<br>
            <br>
            But query execution takes 3.6 seconds. Only 12 rows are
            returned. Adding a limit 1 has no influence.<br>
            <br>
            Postgresql client and server are on the same server, on
            localhost.<br>
            <br>
            I wonder where my 3.5 seconds are going....<br>
            <br>
            Notice that there is no fancy configuration to tell
            Postgresql to evaluate every query plan on earth, that is
            gecoxxxx settings are on their default values.<br>
            <br>
            Any idea on what can be happening that takes so long ?<span
              class=3D"HOEnZb"><font color=3D"#888888"><br>
                <br>
                Franck<br>
                <br>
              </font></span></blockquote>
        </div>
        <br>
      </div>
    </blockquote>
    <br>
  </body>
</html>

--------------070803090408090807090001--

--------------ms020903030307010309020208
Content-Type: application/pkcs7-signature; name="smime.p7s"
Content-Transfer-Encoding: base64
Content-Disposition: attachment; filename="smime.p7s"
Content-Description: Signature cryptographique S/MIME

MIAGCSqGSIb3DQEHAqCAMIACAQExCzAJBgUrDgMCGgUAMIAGCSqGSIb3DQEHAQAAoIINYjCC
BjQwggQcoAMCAQICAR4wDQYJKoZIhvcNAQEFBQAwfTELMAkGA1UEBhMCSUwxFjAUBgNVBAoT
DVN0YXJ0Q29tIEx0ZC4xKzApBgNVBAsTIlNlY3VyZSBEaWdpdGFsIENlcnRpZmljYXRlIFNp
Z25pbmcxKTAnBgNVBAMTIFN0YXJ0Q29tIENlcnRpZmljYXRpb24gQXV0aG9yaXR5MB4XDTA3
MTAyNDIxMDE1NVoXDTE3MTAyNDIxMDE1NVowgYwxCzAJBgNVBAYTAklMMRYwFAYDVQQKEw1T
dGFydENvbSBMdGQuMSswKQYDVQQLEyJTZWN1cmUgRGlnaXRhbCBDZXJ0aWZpY2F0ZSBTaWdu
aW5nMTgwNgYDVQQDEy9TdGFydENvbSBDbGFzcyAxIFByaW1hcnkgSW50ZXJtZWRpYXRlIENs
aWVudCBDQTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAMcJg8zOLdgasSmkLhOr
lr6KMoOMpohBllVHrdRvEg/q6r8jR+EK75xCGhR8ToREoqe7zM9/UnC6TS2y9UKTpT1v7RSM
zR0t6ndl0TWBuUr/UXBhPk+Kmy7bI4yW4urC+y7P3/1/X7U8ocb8VpH/Clt+4iq7nirMcNh6
qJR+xjOhV+VHzQMALuGYn5KZmc1NbJQYclsGkDxDz2UbFqE2+6vIZoL+jb9x4Pa5gNf1TwSD
kOkikZB1xtB4ZqtXThaABSONdfmv/Z1pua3FYxnCFmdr/+N2JLKutIxMYqQOJebr/f/h5t95
m4JgrM3Y/w7YX9d7YAL9jvN4SydHsU6n65cCAwEAAaOCAa0wggGpMA8GA1UdEwEB/wQFMAMB
Af8wDgYDVR0PAQH/BAQDAgEGMB0GA1UdDgQWBBRTcu2SnODaywFcfH6WNU7y1LhRgjAfBgNV
HSMEGDAWgBROC+8apEBbpRdphzDKNGhD0EGu8jBmBggrBgEFBQcBAQRaMFgwJwYIKwYBBQUH
MAGGG2h0dHA6Ly9vY3NwLnN0YXJ0c3NsLmNvbS9jYTAtBggrBgEFBQcwAoYhaHR0cDovL3d3
dy5zdGFydHNzbC5jb20vc2ZzY2EuY3J0MFsGA1UdHwRUMFIwJ6AloCOGIWh0dHA6Ly93d3cu
c3RhcnRzc2wuY29tL3Nmc2NhLmNybDAnoCWgI4YhaHR0cDovL2NybC5zdGFydHNzbC5jb20v
c2ZzY2EuY3JsMIGABgNVHSAEeTB3MHUGCysGAQQBgbU3AQIBMGYwLgYIKwYBBQUHAgEWImh0
dHA6Ly93d3cuc3RhcnRzc2wuY29tL3BvbGljeS5wZGYwNAYIKwYBBQUHAgEWKGh0dHA6Ly93
d3cuc3RhcnRzc2wuY29tL2ludGVybWVkaWF0ZS5wZGYwDQYJKoZIhvcNAQEFBQADggIBAAqD
CH14qywGXLhjjF6uHLkjd02hcdh9hrw+VUsv+q1eeQWB21jWj3kJ96AUlPCoEGZ/ynJNScWy
6QMVQjbbMXltUfO4n4bGGdKo3awPWp61tjAFgraLJgDk+DsSvUD6EowjMTNx25GQgyYJ5RPI
zKKR9tQW8gGK+2+RHxkUCTbYFnL6kl8Ch507rUdPPipJ9CgJFws3kDS3gOS5WFMxcjO5DwKf
KSETEPrHh7p5shuuNktvsv6hxHTLhiMKX893gxdT3XLS9OKmCv87vkINQcNEcIIoFWbP9HOR
z9v3vQwR4e3ksLc2JZOAFK+ssS5XMEoznzpihEP0PLc4dCBYjbvSD7kxgDwZ+Aj8Q9PkbvE9
sIPP7ON0fz095HdThKjiVJe6vofq+n6b1NBc8XdrQvBmunwxD5nvtTW4vtN6VY7mUCmxsCie
uoBJ9OlqmsVWQvifIYf40dJPZkk9YgGTzWLpXDSfLSplbY2LL9C9U0ptvjcDjefLTvqSFc7t
w1sEhF0n/qpA2r0GpvkLRDmcSwVyPvmjFBGqUp/pNy8ZuPGQmHwFi2/14+xeSUDG2bwnsYJQ
G2EdJCB6luQ57GEnTA/yKZSTKI8dDQa8Sd3zfXb19mOgSF0bBdXbuKhEpuP9wirslFe6fQ1t
5j5R0xi72MZ8ikMu1RQZKCyDbMwazlHiMIIHJjCCBg6gAwIBAgIDBNFnMA0GCSqGSIb3DQEB
BQUAMIGMMQswCQYDVQQGEwJJTDEWMBQGA1UEChMNU3RhcnRDb20gTHRkLjErMCkGA1UECxMi
U2VjdXJlIERpZ2l0YWwgQ2VydGlmaWNhdGUgU2lnbmluZzE4MDYGA1UEAxMvU3RhcnRDb20g
Q2xhc3MgMSBQcmltYXJ5IEludGVybWVkaWF0ZSBDbGllbnQgQ0EwHhcNMTIwODI5MjAxNTIz
WhcNMTMwODMxMDg0MTExWjBnMRkwFwYDVQQNExBmQ0cxTUdlTUM1dkZVNVlKMSEwHwYDVQQD
DBhmcmFuY2sucm91dGllckBheGVnZS5jb20xJzAlBgkqhkiG9w0BCQEWGGZyYW5jay5yb3V0
aWVyQGF4ZWdlLmNvbTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAK5kIRjbP769
72PM00wgFczTGqmiU5dAY8XlSziUNq434SJZ3rFZoL0MY6hqVb/p5+u+u6TdhsVywJclPaZE
v+FgGtk74JvlX6oeSWJTOiGLTrk0TRwy7Q+80kbneFdhL+yk/ZTxxcj15IEOeWMuyG/IyePq
H4GtZMkCpsuCOL5bkq9g/H0JHyLSM0tWDbMuD4vKbSeBkzwiz4pSwuANCFMFeRr3d9iZQU0P
VzyKvu/cEUcdoDcVGMuMxX6FwgqrS5c70v/RPM8FafOrqprYfIxVQwxK9IhPgqM9kT6riQo6
OM62d2a21Y6iAeWe/1rssTKn+Stj8jH706LmVJlEGtcCAwEAAaOCA7MwggOvMAkGA1UdEwQC
MAAwCwYDVR0PBAQDAgSwMB0GA1UdJQQWMBQGCCsGAQUFBwMCBggrBgEFBQcDBDAdBgNVHQ4E
FgQUCfIkqGdMRvMTjM6TIpdcUPqdYW8wHwYDVR0jBBgwFoAUU3Ltkpzg2ssBXHx+ljVO8tS4
UYIwIwYDVR0RBBwwGoEYZnJhbmNrLnJvdXRpZXJAYXhlZ2UuY29tMIICIQYDVR0gBIICGDCC
AhQwggIQBgsrBgEEAYG1NwECAjCCAf8wLgYIKwYBBQUHAgEWImh0dHA6Ly93d3cuc3RhcnRz
c2wuY29tL3BvbGljeS5wZGYwNAYIKwYBBQUHAgEWKGh0dHA6Ly93d3cuc3RhcnRzc2wuY29t
L2ludGVybWVkaWF0ZS5wZGYwgfcGCCsGAQUFBwICMIHqMCcWIFN0YXJ0Q29tIENlcnRpZmlj
YXRpb24gQXV0aG9yaXR5MAMCAQEagb5UaGlzIGNlcnRpZmljYXRlIHdhcyBpc3N1ZWQgYWNj
b3JkaW5nIHRvIHRoZSBDbGFzcyAxIFZhbGlkYXRpb24gcmVxdWlyZW1lbnRzIG9mIHRoZSBT
dGFydENvbSBDQSBwb2xpY3ksIHJlbGlhbmNlIG9ubHkgZm9yIHRoZSBpbnRlbmRlZCBwdXJw
b3NlIGluIGNvbXBsaWFuY2Ugb2YgdGhlIHJlbHlpbmcgcGFydHkgb2JsaWdhdGlvbnMuMIGc
BggrBgEFBQcCAjCBjzAnFiBTdGFydENvbSBDZXJ0aWZpY2F0aW9uIEF1dGhvcml0eTADAgEC
GmRMaWFiaWxpdHkgYW5kIHdhcnJhbnRpZXMgYXJlIGxpbWl0ZWQhIFNlZSBzZWN0aW9uICJM
ZWdhbCBhbmQgTGltaXRhdGlvbnMiIG9mIHRoZSBTdGFydENvbSBDQSBwb2xpY3kuMDYGA1Ud
HwQvMC0wK6ApoCeGJWh0dHA6Ly9jcmwuc3RhcnRzc2wuY29tL2NydHUxLWNybC5jcmwwgY4G
CCsGAQUFBwEBBIGBMH8wOQYIKwYBBQUHMAGGLWh0dHA6Ly9vY3NwLnN0YXJ0c3NsLmNvbS9z
dWIvY2xhc3MxL2NsaWVudC9jYTBCBggrBgEFBQcwAoY2aHR0cDovL2FpYS5zdGFydHNzbC5j
b20vY2VydHMvc3ViLmNsYXNzMS5jbGllbnQuY2EuY3J0MCMGA1UdEgQcMBqGGGh0dHA6Ly93
d3cuc3RhcnRzc2wuY29tLzANBgkqhkiG9w0BAQUFAAOCAQEAGSGlokCrFniLxjc6W072LqWy
ISRKEqeC9u0pYSoQGVPAy1mNbu28ThrfAk8umOfFEDkzVH0TXH33TbsCViwsE/rCk6FC0U+Q
AMOn1Ajjf/9z7w8+zCHgmbLyABtYrmBO6AhCD7YLKYPE1VXkJvgdcHCKzVLIkvdIyKSkRn+R
lSorTXhg64lR8vQSX8C9EAY0T/hQyjFS9SDcEhsfOjkYdAiG7fVBft24Gj+3oDgk2479W47l
phG1aHhkflrDeho0h6LnGxY0+PATPuUkvDsr/RFE2VviGFH9UDxjNJmikrmTibCvS4seQFOm
ppHmJzqIcxcn5dqeBDVQYZmLhDkszjGCA90wggPZAgEBMIGUMIGMMQswCQYDVQQGEwJJTDEW
MBQGA1UEChMNU3RhcnRDb20gTHRkLjErMCkGA1UECxMiU2VjdXJlIERpZ2l0YWwgQ2VydGlm
aWNhdGUgU2lnbmluZzE4MDYGA1UEAxMvU3RhcnRDb20gQ2xhc3MgMSBQcmltYXJ5IEludGVy
bWVkaWF0ZSBDbGllbnQgQ0ECAwTRZzAJBgUrDgMCGgUAoIICHTAYBgkqhkiG9w0BCQMxCwYJ
KoZIhvcNAQcBMBwGCSqGSIb3DQEJBTEPFw0xMzA0MDQxNTQ0MDVaMCMGCSqGSIb3DQEJBDEW
BBTwNr4xf1a4ukb1a1j4Ny0QPwrLtDBsBgkqhkiG9w0BCQ8xXzBdMAsGCWCGSAFlAwQBKjAL
BglghkgBZQMEAQIwCgYIKoZIhvcNAwcwDgYIKoZIhvcNAwICAgCAMA0GCCqGSIb3DQMCAgFA
MAcGBSsOAwIHMA0GCCqGSIb3DQMCAgEoMIGlBgkrBgEEAYI3EAQxgZcwgZQwgYwxCzAJBgNV
BAYTAklMMRYwFAYDVQQKEw1TdGFydENvbSBMdGQuMSswKQYDVQQLEyJTZWN1cmUgRGlnaXRh
bCBDZXJ0aWZpY2F0ZSBTaWduaW5nMTgwNgYDVQQDEy9TdGFydENvbSBDbGFzcyAxIFByaW1h
cnkgSW50ZXJtZWRpYXRlIENsaWVudCBDQQIDBNFnMIGnBgsqhkiG9w0BCRACCzGBl6CBlDCB
jDELMAkGA1UEBhMCSUwxFjAUBgNVBAoTDVN0YXJ0Q29tIEx0ZC4xKzApBgNVBAsTIlNlY3Vy
ZSBEaWdpdGFsIENlcnRpZmljYXRlIFNpZ25pbmcxODA2BgNVBAMTL1N0YXJ0Q29tIENsYXNz
IDEgUHJpbWFyeSBJbnRlcm1lZGlhdGUgQ2xpZW50IENBAgME0WcwDQYJKoZIhvcNAQEBBQAE
ggEALyV88eTZAFEVpBkkcwdvPcOum4c/3cNlnOlby+B+6wSrvxsAgeZ2uBzwrzqiBQbQ9tLF
vRV9Djsjd7vXznnp4zbkOMar9rszB+zAY1wtpOC8ARHXsMwob1uNijhXUmqsS8AKrQsb9p8w
4LGbhplDNwOGhmlmkH4pTWVH0FeCV9q2GHbQZqfw2q1iKiOGSX2yd+bOFj+P/Hq2zb6/hIoQ
x7Zqg2BMnDKuSKawnrXeFeWYIFCzXThPUDeKKMbdtNC4dwGEghc5xFJZpW5ShN+OOJCot8D9
eD0PeX4LKuNlfc17WfenFeqsJyCBM6fZIo4mI3RtUsZ3ZmxiYFqOyrHLhAAAAAAAAA==
--------------ms020903030307010309020208--