Extended protocol logging

Started by Dave Cramerabout 19 years ago9 messages
#1Dave Cramer
pg@fastcrypt.com

These are logs from Beta 2.

Did I miss a discussion where we removed the name of the portal
during parse, and bind ?

5715%2006-11-01 01:02:26.631 PST%454862a0.1653%SELECT LOG: execute
S_2: select t0.c_id, t0.c_contact, t0.c_credit_limit, t0.c_state,
t0.c_zip, t0.c_phone, t0.c_credit, t0.c_since, t0.c_ytd_payment,
t0.c_street1, t0.c_balance, t0.c_first, t0.c_last, t0.c_street2,
t0.c_country, t0.c_city from c_customer t0 where t0.c_id = $1 for
update
5715%2006-11-01 01:02:26.631 PST%454862a0.1653%SELECT DETAIL:
parameters: $1 = '44381'

5719%2006-11-01 01:02:28.459 PST%454862a0.1657%SELECT LOG: duration:
4.365 ms
5719%2006-11-01 01:02:28.463 PST%454862a0.1657%PARSE LOG: duration:
0.672 ms
5719%2006-11-01 01:02:28.464 PST%454862a0.1657%BIND LOG: duration:
0.128 ms

Dave

#2Tom Lane
tgl@sss.pgh.pa.us
In reply to: Dave Cramer (#1)
Re: Extended protocol logging

Dave Cramer <pg@fastcrypt.com> writes:

These are logs from Beta 2.

With what logging settings? log_duration has rather different behavior
from what it used to do.

regards, tom lane

#3Simon Riggs
simon@2ndquadrant.com
In reply to: Tom Lane (#2)
Re: Extended protocol logging

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:

Dave Cramer <pg@fastcrypt.com> writes:

These are logs from Beta 2.

With what logging settings? log_duration has rather different behavior
from what it used to do.

I think it would be useful to have the log results from a test program
in the protocol section, so interface designers know what will get
logged from various protocol sequences.

That way JDBC people and others can interpret what their own interfaces
should look like for 8.2

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com

#4Dave Cramer
pg@fastcrypt.com
In reply to: Tom Lane (#2)
Re: Extended protocol logging

On 31-Oct-06, at 11:51 PM, Tom Lane wrote:

Dave Cramer <pg@fastcrypt.com> writes:

These are logs from Beta 2.

With what logging settings? log_duration has rather different
behavior
from what it used to do.

to be honest I don't know, and looking at the logs I suspect that
this is just logging duration, however it's still looking pretty
ambiguous. ( I will get the settings, my client is on the other side
of the world)

what exactly does it mean ? The total operation was 4.365ms and the
parse was .672 and bind was .128? Is it possible for different
connections to be interleaved? I still think having the parse,
bind,execute show the statement name makes sense if for no other
reason than clarity. I would think writing a log parser would be
fairly challenging without them.

Dave

Show quoted text

regards, tom lane

---------------------------(end of
broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

#5Dave Cramer
pg@fastcrypt.com
In reply to: Simon Riggs (#3)
Re: Extended protocol logging

On 1-Nov-06, at 6:18 AM, Simon Riggs wrote:

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:

Dave Cramer <pg@fastcrypt.com> writes:

These are logs from Beta 2.

With what logging settings? log_duration has rather different
behavior
from what it used to do.

I think it would be useful to have the log results from a test program
in the protocol section, so interface designers know what will get
logged from various protocol sequences.

I think some sort of examples are in order, or more consistency.

That way JDBC people and others can interpret what their own
interfaces
should look like for 8.2

from a JDBC point of view we don't look at the logs in the API. I am
just debugging something

Show quoted text

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com

#6Tom Lane
tgl@sss.pgh.pa.us
In reply to: Simon Riggs (#3)
Re: Extended protocol logging

"Simon Riggs" <simon@2ndquadrant.com> writes:

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:

With what logging settings? log_duration has rather different behavior
from what it used to do.

I think it would be useful to have the log results from a test program
in the protocol section,

The contents of the postmaster log are surely not part of the FE protocol.
Clients can't even see the log without resorting to nonstandard hacks.

What it sounds like to me is that Dave's client has got log_duration = ON
when what he should have is log_min_duration_statement = 0. Those two
settings used to be just about redundant but as of 8.2 they have got
distinct functionality. See this thread:
http://archives.postgresql.org/pgsql-hackers/2006-09/msg00681.php

regards, tom lane

#7Simon Riggs
simon@2ndquadrant.com
In reply to: Tom Lane (#6)
Re: Extended protocol logging

On Wed, 2006-11-01 at 10:06 -0500, Tom Lane wrote:

"Simon Riggs" <simon@2ndquadrant.com> writes:

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:

With what logging settings? log_duration has rather different behavior
from what it used to do.

I think it would be useful to have the log results from a test program
in the protocol section,

The contents of the postmaster log are surely not part of the FE protocol.
Clients can't even see the log without resorting to nonstandard hacks.

OK, can we please put the example from -hackers into the docs,
somewhere, with particular note of which protocol messages result in
which logging output?

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com

#8Bruce Momjian
bruce@momjian.us
In reply to: Simon Riggs (#7)
1 attachment(s)
Re: [HACKERS] Extended protocol logging

Simon Riggs wrote:

On Wed, 2006-11-01 at 10:06 -0500, Tom Lane wrote:

"Simon Riggs" <simon@2ndquadrant.com> writes:

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:

With what logging settings? log_duration has rather different behavior
from what it used to do.

I think it would be useful to have the log results from a test program
in the protocol section,

The contents of the postmaster log are surely not part of the FE protocol.
Clients can't even see the log without resorting to nonstandard hacks.

OK, can we please put the example from -hackers into the docs,
somewhere, with particular note of which protocol messages result in
which logging output?

If people want to know the output, run a program and look at the
postmaster logs. If we document it, we have to keep it current, even if
we improve it later. I will say I had trouble testing this logging
because it requires a C program to use that protocol. Here is the test
program I used.

--
Bruce Momjian bruce@momjian.us
EnterpriseDB http://www.enterprisedb.com

+ If your life is a hard drive, Christ can be your backup. +

Attachments:

/pgdev/examples/bindparams.ctext/plainDownload
#9Simon Riggs
simon@2ndquadrant.com
In reply to: Bruce Momjian (#8)
Re: [HACKERS] Extended protocol logging

On Thu, 2006-11-16 at 18:19 -0500, Bruce Momjian wrote:

If we document it, we have to keep it current, even if
we improve it later.

Sounds like all the rest of the docs then...

We really need a guide to deciphering the logs, so that people can
understand how to tune things.

I will say I had trouble testing this logging
because it requires a C program to use that protocol. Here is the test
program I used.

Thanks, I'll look into this.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com