Обсуждение: Printing query durations

Hello,

I am having some trouble getting PostgreSQL to log durations with
statements when called through JDBC.  They appear just fine with
interactive queries using psql, but the duration field does not show up
on JDBC queries.

Is there some configuration I need to pass to the JDBC driver?

Example output from an interactive query:
LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM transaction;

Example output from a JDBC query:
LOG:  statement: SELECT count(*) FROM transaction;

Cheers,
-k

Kevin,

There is no difference between a jdbc query and a psql query. The
backend doesn't know where the query comes from.

DAve
On 27-Mar-06, at 8:26 PM, Kevin Dorne wrote:

> Hello,
>
> I am having some trouble getting PostgreSQL to log durations with
> statements when called through JDBC.  They appear just fine with
> interactive queries using psql, but the duration field does not
> show up
> on JDBC queries.
>
> Is there some configuration I need to pass to the JDBC driver?
>
> Example output from an interactive query:
> LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM
> transaction;
>
> Example output from a JDBC query:
> LOG:  statement: SELECT count(*) FROM transaction;
>
> Cheers,
> -k
>

Dave Cramer <pg@fastcrypt.com> writes:
> There is no difference between a jdbc query and a psql query. The
> backend doesn't know where the query comes from.

However, the backend has different code paths for V2 and V3 protocol,
and it could be that what he's looking at is a deficiency in the V3
protocol logging support.  If so, telling jdbc to use V2 would help.
(I'm being tentative about this because the backend version was not
mentioned --- we've fixed some of that stuff in recent releases.)

            regards, tom lane

On 27-Mar-06, at 10:19 PM, Tom Lane wrote:

> Dave Cramer <pg@fastcrypt.com> writes:
>> There is no difference between a jdbc query and a psql query. The
>> backend doesn't know where the query comes from.
>
> However, the backend has different code paths for V2 and V3 protocol,
> and it could be that what he's looking at is a deficiency in the V3
> protocol logging support.  If so, telling jdbc to use V2 would help.
> (I'm being tentative about this because the backend version was not
> mentioned --- we've fixed some of that stuff in recent releases.)

AFAIR, the deficiencies are in the logging of the prepared
statements. Duration should be logged regardless, no ?
>
>             regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
>                http://archives.postgresql.org
>

Tom Lane wrote:
> Dave Cramer <pg@fastcrypt.com> writes:
>> There is no difference between a jdbc query and a psql query. The
>> backend doesn't know where the query comes from.
>
> However, the backend has different code paths for V2 and V3 protocol,
> and it could be that what he's looking at is a deficiency in the V3
> protocol logging support.  If so, telling jdbc to use V2 would help.
> (I'm being tentative about this because the backend version was not
> mentioned --- we've fixed some of that stuff in recent releases.)

Well, to clarify, we're using PostgreSQL 7.4.7.  I'm not actually sure
what JDBC version we're using, as I've just encountered a
(usefully-named) postgresql.jar file, but I'm fairly certain it's an
8.1.x.  Is there an easy way to tell?

And yes, we are using V3 protocol.

-k

On Tue, 2006-03-28 at 13:26 +1200, Kevin Dorne wrote:

> I am having some trouble getting PostgreSQL to log durations with
> statements when called through JDBC.  They appear just fine with
> interactive queries using psql, but the duration field does not show up
> on JDBC queries.
>
> Is there some configuration I need to pass to the JDBC driver?

These two logging formats are each produced by different parameters:

> Example output from an interactive query:
> LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM transaction;

This is produced by log_min_duration_statement > -1
These lines always have duration prefixes.

> Example output from a JDBC query:
> LOG:  statement: SELECT count(*) FROM transaction;

This is produced by log_statement = 'all'
These lines never have durations.
If you want the matching durations, use log_duration = on and read the
manual to see how to match them up.

The same statement can be logged twice using those options.

http://www.postgresql.org/docs/8.1/static/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-WHAT

Does that answer your query?

Best Regards, Simon Riggs

Hi, Kevin,

Kevin Dorne wrote:

> Well, to clarify, we're using PostgreSQL 7.4.7.  I'm not actually sure
> what JDBC version we're using, as I've just encountered a
> (usefully-named) postgresql.jar file, but I'm fairly certain it's an
> 8.1.x.  Is there an easy way to tell?

public class PGversion {
    public static void main(String[] args) {
        System.err.println( org.postgresql.Driver.getVersion());
    }
}

HTH,
Markus


--
Markus Schaber | Logical Tracking&Tracing International AG
Dipl. Inf.     | Software Development GIS

Fight against software patents in EU! www.ffii.org www.nosoftwarepatents.org

Simon,

What happens if I turn log_duration on ? Doesn't it prepend the
duration to every log ?

Dave
On 28-Mar-06, at 5:32 AM, Simon Riggs wrote:

> On Tue, 2006-03-28 at 13:26 +1200, Kevin Dorne wrote:
>
>> I am having some trouble getting PostgreSQL to log durations with
>> statements when called through JDBC.  They appear just fine with
>> interactive queries using psql, but the duration field does not
>> show up
>> on JDBC queries.
>>
>> Is there some configuration I need to pass to the JDBC driver?
>
> These two logging formats are each produced by different parameters:
>
>> Example output from an interactive query:
>> LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM
>> transaction;
>
> This is produced by log_min_duration_statement > -1
> These lines always have duration prefixes.
>
>> Example output from a JDBC query:
>> LOG:  statement: SELECT count(*) FROM transaction;
>
> This is produced by log_statement = 'all'
> These lines never have durations.
> If you want the matching durations, use log_duration = on and read the
> manual to see how to match them up.
>
> The same statement can be logged twice using those options.
>
> http://www.postgresql.org/docs/8.1/static/runtime-config-
> logging.html#RUNTIME-CONFIG-LOGGING-WHAT
>
> Does that answer your query?
>
> Best Regards, Simon Riggs
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 1: if posting/reading through Usenet, please send an appropriate
>        subscribe-nomail command to majordomo@postgresql.org so that
> your
>        message can get through to the mailing list cleanly
>

On Tue, 2006-03-28 at 07:12 -0500, Dave Cramer wrote:

> What happens if I turn log_duration on ? Doesn't it prepend the
> duration to every log ?

No.

If you use log_statement the statement is logged before execution,
whereas the duration is known only at the end, so two log records are
produced.

log_min_duration_statement logs both at the end so is better suited to
performance analysis.

Best Regards, Simon Riggs

Simon Riggs wrote:
[...]
>> Example output from an interactive query:
>> LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM transaction;
>
> This is produced by log_min_duration_statement > -1
> These lines always have duration prefixes.

Yes, that's what I would expect.  My problem is that this setting only
logs queries via psql; queries via JDBC don't get logged at all.

>> Example output from a JDBC query:
>> LOG:  statement: SELECT count(*) FROM transaction;
>
> This is produced by log_statement = 'all'
> These lines never have durations.
> If you want the matching durations, use log_duration = on and read the
> manual to see how to match them up.

Yes, I've done that.  Again, I can get those durations to appear for
queries via psql, but not via JDBC.

[...]
By the way, the JDBC driver I'm using (thanks Markus Schaber for the
tip) is "PostgreSQL 8.0 JDBC3 with SSL (build 311)".

-k

Kevin,

Well, the server doesn't really know the difference between a query
from jdbc vs a query from psql. The only difference is how they
connect. psql usually connects to a unix domain socket, whereas jdbc
connects via a tcpip socket. Even this behaviour can be changed in
psql by specifying -h <hostname>

What is min_duration set to. Is it possible that the queries are
faster through JDBC. Possibly because the server already has done the
count?

Try setting min_duration to something ridiculously small.

Dave
On 28-Mar-06, at 8:41 PM, Kevin Dorne wrote:

> Simon Riggs wrote:
> [...]
>>> Example output from an interactive query:
>>> LOG:  duration: 109.524 ms  statement: SELECT count(*) FROM
>>> transaction;
>>
>> This is produced by log_min_duration_statement > -1
>> These lines always have duration prefixes.
>
> Yes, that's what I would expect.  My problem is that this setting only
> logs queries via psql; queries via JDBC don't get logged at all.
>
>>> Example output from a JDBC query:
>>> LOG:  statement: SELECT count(*) FROM transaction;
>>
>> This is produced by log_statement = 'all'
>> These lines never have durations.
>> If you want the matching durations, use log_duration = on and read
>> the
>> manual to see how to match them up.
>
> Yes, I've done that.  Again, I can get those durations to appear for
> queries via psql, but not via JDBC.
>
> [...]
> By the way, the JDBC driver I'm using (thanks Markus Schaber for the
> tip) is "PostgreSQL 8.0 JDBC3 with SSL (build 311)".
>
> -k
>

Dave Cramer wrote:
> Kevin,
>
> Well, the server doesn't really know the difference between a query
> from jdbc vs a query from psql. The only difference is how they
> connect. psql usually connects to a unix domain socket, whereas jdbc
> connects via a tcpip socket. Even this behaviour can be changed in  psql
> by specifying -h <hostname>

Well, there is actually quite a big difference.

psql uses the simple query protocol. JDBC uses the extended query protocol.

See previous discussion on -hackers about the difficulties in logging
the extended query protocol usefully..

-O

Dave Cramer wrote:
> Kevin,
>
> Well, the server doesn't really know the difference between a query from
> jdbc vs a query from psql.

Yes, precisely why I am confused.

> The only difference is how they connect. psql
> usually connects to a unix domain socket, whereas jdbc connects via a
> tcpip socket. Even this behaviour can be changed in psql by specifying
> -h <hostname>

Ah, I hadn't thought of that, but it made no difference.

> What is min_duration set to. Is it possible that the queries are faster
> through JDBC. Possibly because the server already has done the count?
>
> Try setting min_duration to something ridiculously small.

No, it's set to 0.  I've also tried 1, 5, and 100, to no effect.

If there really is no inherent difference between how JDBC and psql are
connecting (aside from TCP vs. unix domain socket, which doesn't seem to
make a difference), then I'm lost.

But thanks for the suggestions.

-k

Oliver Jowett wrote:

> psql uses the simple query protocol. JDBC uses the extended query protocol.

Aha.  This came in after my reply went off.  Does seem like a likely
suspect.

Cheers,
-k

Ok, given Oliver's response, try appending ?protocolVersion=2 to the
connect url
On 28-Mar-06, at 9:04 PM, Kevin Dorne wrote:

> Oliver Jowett wrote:
>
>> psql uses the simple query protocol. JDBC uses the extended query
>> protocol.
>
> Aha.  This came in after my reply went off.  Does seem like a likely
> suspect.
>
> Cheers,
> -k
>

Dave Cramer wrote:
> Ok, given Oliver's response, try appending ?protocolVersion=2 to the
> connect url

That does the trick.  I don't think it'll be an issue with this
application to switch to V2, anyway.  Thanks so much, everyone!

-k

Hi, Dave,

Dave Cramer wrote:

> Well, the server doesn't really know the difference between a query
> from jdbc vs a query from psql. The only difference is how they
> connect. psql usually connects to a unix domain socket, whereas jdbc
> connects via a tcpip socket.

That's not strictly true, there are more possible differences, AFAIR:

V2 vs. V3 protocol.

Plain statement vs. PREPARE and EXECUTE vs. DECLARE CURSOR / FETCH vs.
V3 protocol-level prepare and bind.

confusing,
Markus
--
Markus Schaber | Logical Tracking&Tracing International AG
Dipl. Inf.     | Software Development GIS

Fight against software patents in EU! www.ffii.org www.nosoftwarepatents.org