Re: Change in Log Format and Prepared Statements

On 09/19/2012 02:32 PM, Tom Lane wrote:
> Craig Ringer <ringerc(at)ringerc(dot)id(dot)au> writes:
>> On 09/17/2012 02:45 PM, Alexander Stanier wrote:
>>> Does anyone know what the three durations specifically represent?
>
>> I have no idea, honestly. Maybe ask on pgsql-general ?
>
> Parse, bind, execute phases of extended-query protocol?
>
> http://www.postgresql.org/docs/9.2/static/protocol-flow.html#PROTOCOL-FLOW-EXT-QUERY
>
>> I strongly agree. Three separate log lines for timing, with no
>> indication about which is which, sucks.
>
> 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

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

Does all this verbosity really need to be displayed by `log_duration`
even when `log_min_messages` is at the default? It feels like
implementation detail / debug trace stuff, not something that should be
visible to day to day users and admins who just want to log statement
durations. They don't care if the client is using the extended query
protocol or not.

I think this is a bit of a usability wart.

How, at the default log level, does it convey any useful information
whatsoever?

LOG: execute <unnamed>: INSERT INTO testrs VALUES (1)
LOG: duration: 0.109 ms
LOG: duration: 0.026 ms
LOG: duration: 0.031 ms
LOG: duration: 0.005 ms
LOG: execute <unnamed>: INSERT INTO testrs VALUES (2)
LOG: duration: 0.029 ms
LOG: duration: 0.023 ms
LOG: duration: 0.021 ms
LOG: duration: 0.004 ms

There's no reliable way to associate the durations with the statements
in case of interleaving, and nothing that tells you what the durations
are. Here's what I'd want to see as the *default:

LOG: [4067] execute <unnamed>: INSERT INTO testrs VALUES (1)
LOG: [4067] duration: 0.161 ms

If durations are logged on a separate line, a reliable way to associate
them - be it backend pid, vtxid, or whatever - needs to be logged by
default, and IMO the durations need to be reported as a single overall
time with the command-tag of the associated command (if shown in user's
log_line_prefix).

Thoughts/opinions?

--
Craig Ringer