Thread: Extended protocol logging

Extended protocol logging

From
Dave Cramer
Date:
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


Re: Extended protocol logging

From
Tom Lane
Date:
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


Re: Extended protocol logging

From
"Simon Riggs"
Date:
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




Re: Extended protocol logging

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



Re: Extended protocol logging

From
Dave Cramer
Date:
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
>
> -- 
>   Simon Riggs
>   EnterpriseDB   http://www.enterprisedb.com
>
>
>



Re: Extended protocol logging

From
"Simon Riggs"
Date:
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




Re: Extended protocol logging

From
Tom Lane
Date:
"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