Thread: 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
Attachment
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
Attachment
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
Attachment
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
Attachment
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
Attachment
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
Attachment
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