Re: Extended protocol logging

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

Dave Cramer <pg(at)fastcrypt(dot)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

On Tue, 2006-10-31 at 23:51 -0500, Tom Lane wrote:
> Dave Cramer <pg(at)fastcrypt(dot)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

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

> Dave Cramer <pg(at)fastcrypt(dot)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
>
> regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

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(at)fastcrypt(dot)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
>
> --
> Simon Riggs
> EnterpriseDB http://www.enterprisedb.com
>
>
>

"Simon Riggs" <simon(at)2ndquadrant(dot)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

On Wed, 2006-11-01 at 10:06 -0500, Tom Lane wrote:
> "Simon Riggs" <simon(at)2ndquadrant(dot)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

Simon Riggs wrote:
> On Wed, 2006-11-01 at 10:06 -0500, Tom Lane wrote:
> > "Simon Riggs" <simon(at)2ndquadrant(dot)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(at)momjian(dot)us
EnterpriseDB http://www.enterprisedb.com

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

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