Re: Change in Log Format and Prepared Statements

Craig Ringer <ringerc@ringerc.id.au> writes:
> On 09/19/2012 02:32 PM, Tom Lane wrote:
>> AFAICT from looking at the backend code, they are labeled ...

> Yes, they have command tags, and if a suitable log_line_prefix like:

>      log_line_prefix = 'cmd=%i pid=%p '

> is set they are visible:

> cmd=INSERT pid=4067 LOG:  execute <unnamed>: INSERT INTO hold VALUES (1)
> cmd=INSERT pid=4067 LOG:  duration: 1.454 ms
> cmd=PARSE pid=4067 LOG:  duration: 0.066 ms
> cmd=PARSE pid=4067 LOG:  duration: 0.028 ms
> cmd=BIND pid=4067 LOG:  duration: 0.007 ms

Oh.  You are talking about log_duration output, which is *meant* to be
terse.  It's designed that way for high-query-volume installations that
can't afford more log text than that.  If you want something that's more
easily readable, turn that off and instead set
log_min_duration_statement to zero, as indeed is recommended in the
documentation.

> but that just makes things more confusing. What's with the two PARSEs?
> and why is the INSERT logged *before* the PARSE and BIND?

It's hard to be sure without seeing the more verbose logging, but
I think you are looking at interleaved parsing/execution of multiple
prepared statements.  Because that's allowed, simplifying the logging as
you suggest doesn't seem very practical.

My recollection is that the current behavior of the duration-logging
options was hashed out in considerable detail some years ago, and is
meant to serve multiple sets of requirements.  It's not going to be
that easy to persuade people to change it.

            regards, tom lane