Thread: duration logging setting in 7.4
Hi. I'm trying to set run-time environment in pgsql7.4 so, that it prints all statements with duration time, but I can't understand why setting log_min_duration_statement to '0' causes printing to syslog plenty of lines ending with 'duration: statement:', i.e. without any statement string (except expected ones). Can anybody help me? Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
Ryszard Lach wrote:
>
> Hi.
>
> I'm trying to set run-time environment in pgsql7.4 so, that it prints
> all statements with duration time, but I can't understand why setting
> log_min_duration_statement to '0' causes printing to syslog plenty of
> lines ending with 'duration: statement:', i.e. without any statement
> string (except expected ones). Can anybody help me?
Can you show us some of the log file? If I do:
test=> set log_min_duration_statement = 0;
SET
test=> select 1;
?column?
----------
1
(1 row)
I get:
LOG: duration: 0.861 ms statement: select 1;
--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073
On Mon, Nov 17, 2003 at 09:37:07PM -0500, Bruce Momjian wrote: > Ryszard Lach wrote: > > > > Hi. > > > > I'm trying to set run-time environment in pgsql7.4 so, that it prints > > all statements with duration time, but I can't understand why setting > > log_min_duration_statement to '0' causes printing to syslog plenty of > > lines ending with 'duration: statement:', i.e. without any statement > > string (except expected ones). Can anybody help me? > > Can you show us some of the log file? If I do: > Sure. Nov 18 10:05:20 postgres[1348]: [318-1] LOG: duration: 0.297 ms statement: Nov 18 10:05:20 postgres[1311]: [5477-1] LOG: duration: 0.617 ms statement: Nov 18 10:05:20 postgres[1312]: [5134-1] LOG: duration: 0.477 ms statement: Nov 18 10:05:20 postgres[1349]: [318-1] LOG: duration: 0.215 ms statement: Nov 18 10:05:20 postgres[1313]: [5449-1] LOG: duration: 0.512 ms statement: Nov 18 10:05:20 postgres[1314]: [5534-1] LOG: duration: 0.420 ms statement: Nov 18 10:05:20 postgres[1330]: [772-1] LOG: duration: 1.386 ms statement: SELECT * FROM mytablemius WHERE id = 0; Nov 18 10:05:20 postgres[1315]: [5757-1] LOG: duration: 0.417 ms statement: Nov 18 10:05:20 postgres[1316]: [5885-1] LOG: duration: 0.315 ms statement: Nov 18 10:05:20 postgres[1317]: [5914-1] LOG: duration: 0.301 ms statement: Nov 18 10:05:20 postgres[1318]: [5990-1] LOG: duration: 0.293 ms statement: Nov 18 10:05:20 postgres[1319]: [6009-1] LOG: duration: 0.211 ms statement: Nov 18 10:05:20 postgres[1320]: [6039-1] LOG: duration: 0.188 ms statement: this is with setting log_duration = false log_statement = false log_min_duration_statement = 0 The amount of lines containing statement string is nearly the same ase before upgrade (from 7.3), all other lines are extra. I don't know if this can be a reason, this is on a pretty busy machine (ca. 100 selects/second, but loadavg lower then 0.9), I'm logging postgres through syslog. Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
Wow, that is strange. If you don't use syslog, do you see the proper output? If you turn on log_statement, do you see the statements? --------------------------------------------------------------------------- Ryszard Lach wrote: > On Mon, Nov 17, 2003 at 09:37:07PM -0500, Bruce Momjian wrote: > > Ryszard Lach wrote: > > > > > > Hi. > > > > > > I'm trying to set run-time environment in pgsql7.4 so, that it prints > > > all statements with duration time, but I can't understand why setting > > > log_min_duration_statement to '0' causes printing to syslog plenty of > > > lines ending with 'duration: statement:', i.e. without any statement > > > string (except expected ones). Can anybody help me? > > > > Can you show us some of the log file? If I do: > > > > Sure. > > Nov 18 10:05:20 postgres[1348]: [318-1] LOG: duration: 0.297 ms statement: > Nov 18 10:05:20 postgres[1311]: [5477-1] LOG: duration: 0.617 ms statement: > Nov 18 10:05:20 postgres[1312]: [5134-1] LOG: duration: 0.477 ms statement: > Nov 18 10:05:20 postgres[1349]: [318-1] LOG: duration: 0.215 ms statement: > Nov 18 10:05:20 postgres[1313]: [5449-1] LOG: duration: 0.512 ms statement: > Nov 18 10:05:20 postgres[1314]: [5534-1] LOG: duration: 0.420 ms statement: > Nov 18 10:05:20 postgres[1330]: [772-1] LOG: duration: 1.386 ms statement: SELECT * FROM mytablemius WHERE id = 0; > Nov 18 10:05:20 postgres[1315]: [5757-1] LOG: duration: 0.417 ms statement: > Nov 18 10:05:20 postgres[1316]: [5885-1] LOG: duration: 0.315 ms statement: > Nov 18 10:05:20 postgres[1317]: [5914-1] LOG: duration: 0.301 ms statement: > Nov 18 10:05:20 postgres[1318]: [5990-1] LOG: duration: 0.293 ms statement: > Nov 18 10:05:20 postgres[1319]: [6009-1] LOG: duration: 0.211 ms statement: > Nov 18 10:05:20 postgres[1320]: [6039-1] LOG: duration: 0.188 ms statement: > > > this is with setting > > log_duration = false > log_statement = false > log_min_duration_statement = 0 > > The amount of lines containing statement string is nearly the same ase before > upgrade (from 7.3), all other lines are extra. > > I don't know if this can be a reason, this is on a pretty busy machine (ca. 100 > selects/second, but loadavg lower then 0.9), I'm logging postgres through syslog. > > Richard. > > -- > "First they ignore you. Then they laugh at you. Then they > fight you. Then you win." - Mohandas Gandhi. > -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073
Ryszard Lach wrote: > If I turn on log_min_duration_statement (i.e. set to 0), log_statement and > log_duration, then I receive something like that > > Nov 17 22:33:27 postgres[22945]: [29231-1] LOG: statement: > Nov 17 22:33:27 postgres[22945]: [29232-1] LOG: duration: 0.198 ms > Nov 17 22:33:27 postgres[22945]: [29233-1] LOG: duration: 0.198 ms statement: > Nov 17 22:33:27 postgres[22946]: [29231-1] LOG: statement: > Nov 17 22:33:27 postgres[22946]: [29232-1] LOG: duration: 0.191 ms > Nov 17 22:33:27 postgres[22946]: [29233-1] LOG: duration: 0.191 ms statement: > Nov 17 22:33:27 postgres[22678]: [147134-1] LOG: statement: select * from cms where id=1465 > Nov 17 22:33:27 postgres[22679]: [154907-1] LOG: statement: > Nov 17 22:33:27 postgres[22679]: [154908-1] LOG: duration: 0.867 ms > Nov 17 22:33:27 postgres[22679]: [154909-1] LOG: duration: 0.867 ms statement: > Nov 17 22:33:27 postgres[22678]: [147135-1] LOG: duration: 1.458 ms > Nov 17 22:33:27 postgres[22678]: [147136-1] LOG: duration: 1.458 ms statement: select * from cms where id=1465 > Nov 17 22:33:27 postgres[22680]: [158366-1] LOG: statement: > Nov 17 22:33:27 postgres[22680]: [158367-1] LOG: duration: 0.620 ms > Nov 17 22:33:27 postgres[22680]: [158368-1] LOG: duration: 0.620 ms statement: > Nov 17 22:33:27 postgres[22681]: [161294-1] LOG: statement: > Nov 17 22:33:27 postgres[22681]: [161295-1] LOG: duration: 0.650 ms > > It seems, that log_duration is responsible only for "duration:" lines, > log_statement - for "statement:" ones, and "log_min_duration_statement" - for > "duration: .* statement:". I think, that the above output should exclude losing > of data by syslog from further delibarations. Do you thing that could be > a bug? Yes, the problem is not related to syslog. Are you using prepared queries, perhaps? I don't think those show the query, but it seems we should display something better than blanks. > There is another one thing: logs from the same database running on 7.3 and the same > application contained lines like 'select getdatabaseencoding()', 'select > datestyle()' and similar (not used by application explicite, probably > added by JDBC driver), now they are missed - maybe this is the > problem? No, those are missing because the new 7.4 wire protocol doesn't require those queries anymore --- the data is send automatically. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073
On Tue, Nov 18, 2003 at 10:07:48AM -0500, Bruce Momjian wrote: > > Wow, that is strange. If you don't use syslog, do you see the proper > output? I've just checked this. It behaves exactly the same way. > If you turn on log_statement, do you see the statements? If I turn on log_min_duration_statement (i.e. set to 0), log_statement and log_duration, then I receive something like that Nov 17 22:33:27 postgres[22945]: [29231-1] LOG: statement: Nov 17 22:33:27 postgres[22945]: [29232-1] LOG: duration: 0.198 ms Nov 17 22:33:27 postgres[22945]: [29233-1] LOG: duration: 0.198 ms statement: Nov 17 22:33:27 postgres[22946]: [29231-1] LOG: statement: Nov 17 22:33:27 postgres[22946]: [29232-1] LOG: duration: 0.191 ms Nov 17 22:33:27 postgres[22946]: [29233-1] LOG: duration: 0.191 ms statement: Nov 17 22:33:27 postgres[22678]: [147134-1] LOG: statement: select * from cms where id=1465 Nov 17 22:33:27 postgres[22679]: [154907-1] LOG: statement: Nov 17 22:33:27 postgres[22679]: [154908-1] LOG: duration: 0.867 ms Nov 17 22:33:27 postgres[22679]: [154909-1] LOG: duration: 0.867 ms statement: Nov 17 22:33:27 postgres[22678]: [147135-1] LOG: duration: 1.458 ms Nov 17 22:33:27 postgres[22678]: [147136-1] LOG: duration: 1.458 ms statement: select * from cms where id=1465 Nov 17 22:33:27 postgres[22680]: [158366-1] LOG: statement: Nov 17 22:33:27 postgres[22680]: [158367-1] LOG: duration: 0.620 ms Nov 17 22:33:27 postgres[22680]: [158368-1] LOG: duration: 0.620 ms statement: Nov 17 22:33:27 postgres[22681]: [161294-1] LOG: statement: Nov 17 22:33:27 postgres[22681]: [161295-1] LOG: duration: 0.650 ms It seems, that log_duration is responsible only for "duration:" lines, log_statement - for "statement:" ones, and "log_min_duration_statement" - for "duration: .* statement:". I think, that the above output should exclude losing of data by syslog from further delibarations. Do you thing that could be a bug? There is another one thing: logs from the same database running on 7.3 and the same application contained lines like 'select getdatabaseencoding()', 'select datestyle()' and similar (not used by application explicite, probably added by JDBC driver), now they are missed - maybe this is the problem? Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
On Wed, Nov 19, 2003 at 01:58:27PM -0500, Bruce Momjian wrote: > Ryszard Lach wrote: > > > There is another one thing: logs from the same database running on 7.3 and the same > > application contained lines like 'select getdatabaseencoding()', 'select > > datestyle()' and similar (not used by application explicite, probably > > added by JDBC driver), now they are missed - maybe this is the > > problem? > > No, those are missing because the new 7.4 wire protocol doesn't require > those queries anymore --- the data is send automatically. > Mayby this is a solution? Because of some charset-related problems we are still using an old (AFAiR modified) version of JDBC driver. I'm not a programmer, but I think and don't know what JDBC driver does, but maybe it sends from client side those queries and server doesn't know what to do with them? I'll ask our programmers to try with 7.4 driver and tell you about results. Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
Ryszard Lach wrote: > On Wed, Nov 19, 2003 at 01:58:27PM -0500, Bruce Momjian wrote: > > Ryszard Lach wrote: > > > > > There is another one thing: logs from the same database running on 7.3 and the same > > > application contained lines like 'select getdatabaseencoding()', 'select > > > datestyle()' and similar (not used by application explicite, probably > > > added by JDBC driver), now they are missed - maybe this is the > > > problem? > > > > No, those are missing because the new 7.4 wire protocol doesn't require > > those queries anymore --- the data is send automatically. > > > > Mayby this is a solution? Because of some > charset-related problems we are still using an old (AFAiR modified) > version of JDBC driver. I'm not a programmer, but I think and don't know > what JDBC driver does, but maybe it sends from client side those queries > and server doesn't know what to do with them? I'll ask our programmers > to try with 7.4 driver and tell you about results. Also, try plain psql and issue a query and see if it appears. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073
Ryszard Lach <siaco@autograf.pl> writes:
> Nov 18 10:05:20 postgres[1348]: [318-1] LOG: duration: 0.297 ms statement:
> Nov 18 10:05:20 postgres[1311]: [5477-1] LOG: duration: 0.617 ms statement:
> Nov 18 10:05:20 postgres[1312]: [5134-1] LOG: duration: 0.477 ms statement:
> Nov 18 10:05:20 postgres[1349]: [318-1] LOG: duration: 0.215 ms statement:
> Nov 18 10:05:20 postgres[1313]: [5449-1] LOG: duration: 0.512 ms statement:
> Nov 18 10:05:20 postgres[1314]: [5534-1] LOG: duration: 0.420 ms statement:
> Nov 18 10:05:20 postgres[1330]: [772-1] LOG: duration: 1.386 ms statement: SELECT * FROM mytablemius WHERE id = 0;
> Nov 18 10:05:20 postgres[1315]: [5757-1] LOG: duration: 0.417 ms statement:
> Nov 18 10:05:20 postgres[1316]: [5885-1] LOG: duration: 0.315 ms statement:
> Nov 18 10:05:20 postgres[1317]: [5914-1] LOG: duration: 0.301 ms statement:
> Nov 18 10:05:20 postgres[1318]: [5990-1] LOG: duration: 0.293 ms statement:
> Nov 18 10:05:20 postgres[1319]: [6009-1] LOG: duration: 0.211 ms statement:
> Nov 18 10:05:20 postgres[1320]: [6039-1] LOG: duration: 0.188 ms statement:
Is it possible that you're sending a lot of queries that have an initial
newline in the text? I'd expect the first line of log output for such a
query to look as above.
regards, tom lane
---------------------------(end of broadcast)---------------------------
TIP 3: 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 Thu, Nov 20, 2003 at 07:17:01PM -0500, Tom Lane wrote: > > > Is it possible that you're sending a lot of queries that have an initial > newline in the text? I'd expect the first line of log output for such a > query to look as above. I don't think so, but it is possible, that queries have e.g. two semicolons on end - I've just noticed, that separating two queries with two or more semicolons gives one empty log entry for each redundand semicolon. We'll debug our application keeping this in mind. Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
Ryszard Lach <ryszard@lach.name> writes:
> It seems, that empty statements are generated during opening of
> connection.
Hmm. Try asking about that on the pgsql-jdbc list. I think the JDBC
driver must actually be sending empty commands.
Looking at the backend code, I realize that 7.4 will emit LOG: entries
for empty query strings, whereas prior releases would not. This isn't
a bug IMHO, but it does explain why you are noticing output that wasn't
there before you updated to 7.4.
regards, tom lane
Hi, again. I've turned on only log_connections and log_statement. See the following log fragment (I've included lines only related to opening of new connection); Nov 21 11:06:44 postgres[3359]: [3-1] LOG: connection received: host= port= Nov 21 11:06:44 postgres[3359]: [4-1] LOG: connection authorized: user=pracuj database=pracuj Nov 21 11:06:44 postgres[3359]: [5-1] LOG: statement: set datestyle to 'ISO'; select version(), case when pg_encoding_to_char(1)= 'SQL_ASCII' then 'UNKNOWN' else Nov 21 11:06:44 postgres[3359]: [5-2] getdatabaseencoding() end; Nov 21 11:06:44 postgres[3359]: [6-1] LOG: statement: Nov 21 11:06:44 postgres[3359]: [7-1] LOG: statement: select * from ... Nov 21 11:06:45 postgres[3376]: [3-1] LOG: connection received: host= port= Nov 21 11:06:45 postgres[3376]: [4-1] LOG: connection authorized: user=pracuj database=pracuj Nov 21 11:06:45 postgres[3376]: [5-1] LOG: statement: set datestyle to 'ISO'; select version(), case when pg_encoding_to_char(1)= 'S QL_ASCII' then ' else Nov 21 11:06:45 postgres[3376]: [5-2] getdatabaseencoding() end; Nov 21 11:06:45 postgres[3376]: [6-1] LOG: statement: It seems, that empty statements are generated during opening of connection. Please, note also: 1. We are using an older jdbc driver (pgjdbc2) 2. We ar using encoding in URL (jdbc:postgresql://localhost:5432/database?charSet=iso-8859-1) Richard. -- "First they ignore you. Then they laugh at you. Then they fight you. Then you win." - Mohandas Gandhi.
Ryszard Lach <siaco@autograf.pl> writes:
> Nov 18 10:05:20 postgres[1348]: [318-1] LOG: duration: 0.297 ms statement:
> Nov 18 10:05:20 postgres[1311]: [5477-1] LOG: duration: 0.617 ms statement:
> Nov 18 10:05:20 postgres[1312]: [5134-1] LOG: duration: 0.477 ms statement:
> Nov 18 10:05:20 postgres[1349]: [318-1] LOG: duration: 0.215 ms statement:
> Nov 18 10:05:20 postgres[1313]: [5449-1] LOG: duration: 0.512 ms statement:
> Nov 18 10:05:20 postgres[1314]: [5534-1] LOG: duration: 0.420 ms statement:
> Nov 18 10:05:20 postgres[1330]: [772-1] LOG: duration: 1.386 ms statement: SELECT * FROM mytablemius WHERE id = 0;
> Nov 18 10:05:20 postgres[1315]: [5757-1] LOG: duration: 0.417 ms statement:
> Nov 18 10:05:20 postgres[1316]: [5885-1] LOG: duration: 0.315 ms statement:
> Nov 18 10:05:20 postgres[1317]: [5914-1] LOG: duration: 0.301 ms statement:
> Nov 18 10:05:20 postgres[1318]: [5990-1] LOG: duration: 0.293 ms statement:
> Nov 18 10:05:20 postgres[1319]: [6009-1] LOG: duration: 0.211 ms statement:
> Nov 18 10:05:20 postgres[1320]: [6039-1] LOG: duration: 0.188 ms statement:
Is it possible that you're sending a lot of queries that have an initial
newline in the text? I'd expect the first line of log output for such a
query to look as above.
regards, tom lane
---------------------------(end of broadcast)---------------------------
TIP 3: 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