From: Tom Lane <tgl@sss.pgh.pa.us>
To: devel.brain99@xoxy.net
cc: pgsql-performance@postgresql.org
Subject: Re: Random slow queries
In-reply-to: 
 <CACjsgD=Pg3utmjD8F3ZSYXYnb+2CjuxyDzNbrfwA-_giWGM1sA@mail.gmail.com>
References: 
 <CACjsgDm+n0s=5cMwGF7nRMXS8fX6CF9t1HsOr_M2iejpxKgS1A@mail.gmail.com>
 <DM2PR07MB5578DB88C4DCCEA3213FA76DA230@DM2PR07MB557.namprd07.prod.outlook.com>
 <CACjsgD=Pg3utmjD8F3ZSYXYnb+2CjuxyDzNbrfwA-_giWGM1sA@mail.gmail.com>
Comments: In-reply-to devel.brain99@xoxy.net
	message dated "Wed, 29 Jun 2016 20:04:31 +0200"
Date: Wed, 29 Jun 2016 16:20:31 -0400
Message-ID: <29847.1467231631@sss.pgh.pa.us>
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

devel.brain99@xoxy.net writes:
> As you can see from the logs I posted, it appears the execution plan was
> cached (LOG:  duration: 122006.000 ms  bind cached-1453392550: select....).
> Maybe those aren't processed by auto_explain?

In that, "cached-1453392550" is a statement name given by the client;
you'd know better than we do where it's coming from, but it has no
particular significance to the server.

The real information here is that what is taking 122 seconds is the BIND
step of extended query protocol.  That explains why auto_explain doesn't
notice it; auto_explain only instruments the execution phase.  Typically,
what takes time in the BIND step is planning the query, so it seems like
we have to conclude that something in planning is getting hung up.  That
doesn't get us very much closer to an explanation though :-(.

Don't know if it would be practical for you at all, but if you could
attach to a process that's stuck like this with a debugger and get a stack
trace, that would probably be very informative.

https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend

			regards, tom lane


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance