Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian writes: Imagine someone always having log_statement on and doing some sort of aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that someone (or maybe the admin on the night shift, to make it more dramatic) also turns on log_min_statement_duration (or whatever it's spelled), say to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head -10. In order to guarantee the consistency of both results, you'd have to log each query twice in this case. I guess. Can we agree to this? * If log_statement is on, then we log query: %s (Should it be statement: %s?) %s has newlines suitable escaped; exactly how is independent of this discussion. * If log_duration is on, then we log duration: x.xxx ms The user can use log_pid to link it to the statement. (If the user doesn't like this, he can use log_min_duration_statement=0.) * If log_min_duration_statement is triggered, then we log duration: x.xxx ms; query: %s * If log_statement is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or (b) log only log_min_duration_statement * If log_duration is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or (b) log only log_min_duration_statement -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut wrote: Bruce Momjian writes: Imagine someone always having log_statement on and doing some sort of aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that someone (or maybe the admin on the night shift, to make it more dramatic) also turns on log_min_statement_duration (or whatever it's spelled), say to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head -10. In order to guarantee the consistency of both results, you'd have to log each query twice in this case. I guess. Can we agree to this? * If log_statement is on, then we log query: %s (Should it be statement: %s?) %s has newlines suitable escaped; exactly Yes, it should be 'statement'. how is independent of this discussion. People didn't like the newlines changed because it makes large queries hard to read (all on one line), and we had to double-escape backslashes, meaning the logged query had different backslashing from the original. * If log_duration is on, then we log duration: x.xxx ms The user can use log_pid to link it to the statement. (If the user doesn't like this, he can use log_min_duration_statement=0.) Exactly. log_min_duration_statement=0 delays the print of the statement until it completes, but it prints them together. * If log_min_duration_statement is triggered, then we log duration: x.xxx ms; query: %s * If log_statement is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or I think we have to log both because perhaps they want the query printed before it completes. (b) log only log_min_duration_statement * If log_duration is on and log_min_duration_statement is triggered, then we (pick one): (a) log both as per above, or (b) log only log_min_duration_statement Good point. Right now we do only: duration: x.xxx ms; query: %s This seems wrong because it isn't consistent with log_statement. Glad you pointed that out. The only argument for printing one one is that there isn't any value to printing the duration separately, because it isn't printing before the query. However, for consistency, I think you are right we should print both. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [PATCHES] fix log_min_duration_statement logic error
pgman wrote: OK, patch attached and applied. Changes are: query: now statement: log_duration also now prints when log_min_duration_statement prints Oh, sample is: LOG: statement: select 1; LOG: duration: 0.329 ms LOG: duration: 0.329 ms statement: select 1; -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian writes: Another idea if you like consistency would be: LOG: duration: 4.056 ms query: select * \nfrom pg_language; Speaking of consistency... Imagine someone always having log_statement on and doing some sort of aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that someone (or maybe the admin on the night shift, to make it more dramatic) also turns on log_min_statement_duration (or whatever it's spelled), say to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head -10. In order to guarantee the consistency of both results, you'd have to log each query twice in this case. -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian writes: I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, Then how would you identify the real tabs in the data? -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut wrote: Bruce Momjian writes: Another idea if you like consistency would be: LOG: duration: 4.056 ms query: select * \nfrom pg_language; Speaking of consistency... Imagine someone always having log_statement on and doing some sort of aggregate query counting, say like grep '^LOG: query:' | wc -l. Now that someone (or maybe the admin on the night shift, to make it more dramatic) also turns on log_min_statement_duration (or whatever it's spelled), say to find the slowest queries: grep '^LOG: duration:' | sort -xyz | head -10. In order to guarantee the consistency of both results, you'd have to log each query twice in this case. I guess. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: Agreed. elog is the proper place, because then you guarantee that it is all on one line. Is that OK? Do we have elogs that we want over several lines? Is this something we can do at this stage in beta? As to the latter: sure. We've already hacked the formatting of the log output quite a bit since 7.3. Better to hit them with this too now, than spread the pain over multiple releases. As to the former: the only thing that seems debatable to me is what to do about the layout of the new multi-part ereport() messages. I would be inclined to go for one line per part, viz ERROR: blah blah blah DETAIL: blah blah\nblah blah HINT: blah blah\nblah blah\nblah blah but perhaps someone would like to argue for somehow collapsing all this to one line? If so, how exactly? regards, tom lane ---(end of broadcast)--- TIP 8: explain analyze is your friend
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: Agreed. elog is the proper place, because then you guarantee that it is all on one line. Is that OK? Do we have elogs that we want over several lines? Is this something we can do at this stage in beta? As to the latter: sure. We've already hacked the formatting of the log output quite a bit since 7.3. Better to hit them with this too now, than spread the pain over multiple releases. As to the former: the only thing that seems debatable to me is what to do about the layout of the new multi-part ereport() messages. I would be inclined to go for one line per part, viz ERROR: blah blah blah DETAIL: blah blah\nblah blah HINT: blah blah\nblah blah\nblah blah but perhaps someone would like to argue for somehow collapsing all this to one line? If so, how exactly? Are those lines sent to the elog as one write() or separate ones --- do they always appear together in the log? I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, so the output looks like: LOG: duration: 4.035 ms query: select * from pg_language; This makes the logs look better, and it is easier for script to grab queries. Grep doesn't work as well, but I think that is OK. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: Are those lines sent to the elog as one write() or separate ones --- do they always appear together in the log? Currently they are sent in a single fprintf(stderr), which might or might not be good enough to ensure atomicity. We could hack this to a direct write() if you don't mind depending on fileno(stderr), but I think that'd create some portability issues on non-Unix platforms. If you're using syslog then I think all bets are off anyway. I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, That's a thought... seems less invasive than the backslashing. Not sure how well it'll work for syslog output though. regards, tom lane ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] fix log_min_duration_statement logic error
On Mon, Oct 06, 2003 at 10:42:57AM -0400, Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, That's a thought... seems less invasive than the backslashing. Not sure how well it'll work for syslog output though. Not good. Some syslogs will replace the literal tab with a ^I. Maybe it should be a bunch of spaces when using syslog. It seems a good idea to me anyway. How would it handle multiple fields? Say LOG: blah blah DETAIL: something HINT: something else Will it be LOG: blah blah DETAIL: something else HINT: something else ? -- Alvaro Herrera ([EMAIL PROTECTED]) Find a bug in a program, and fix it, and the program will work today. Show the program how to find and fix a bug, and the program will work forever (Oliver Silfridge) ---(end of broadcast)--- TIP 8: explain analyze is your friend
Re: [PATCHES] fix log_min_duration_statement logic error
Alvaro Herrera Munoz [EMAIL PROTECTED] writes: Bruce Momjian [EMAIL PROTECTED] writes: I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, Not good. Some syslogs will replace the literal tab with a ^I. That seems okay. We just want to make sure continuation lines are easily distinguishable. (But leading spaces would be okay with me too.) How would it handle multiple fields? Say LOG: blah blah DETAIL: something HINT: something else Will it be LOG: blah blah DETAIL: something else HINT: something else No, one would hope no tab before DETAIL/HINT/etc. The idea is to be able to recognize when the contents of one of these entries spans lines. regards, tom lane ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Alvaro Herrera Munoz [EMAIL PROTECTED] writes: Bruce Momjian [EMAIL PROTECTED] writes: I had a new idea on output format. Instead of converting newline to \n, and double-escaping backslashes, we add a tab after any newline, Not good. Some syslogs will replace the literal tab with a ^I. That seems okay. We just want to make sure continuation lines are easily distinguishable. (But leading spaces would be okay with me too.) Agreed. It is easy to strip off the tab to rebuild the original query --- striping off 8 spaces seems less logical. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 8: explain analyze is your friend
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane writes: Sure it can. You're essentially arguing that DBAs are too dumb to match up matching query and duration log outputs. I don't buy that. I think they'll be analyzing their logs with little Perl scripts anyway, and that consistency of log output format will be worth more to those scripts than sometimes having related items all on one log line. When you're dealing with a large installation, these little Perl scripts become difficult. I've just had to deal with a similar issue with a popular MTA which spreads the relevant log information over several lines. If you're generating 500 MB of log output a day, it becomes a problem. -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane writes: I would prefer to see the log entries look like LOG: query: select * from pg_class; LOG: duration: nn.nnn msec I'm not fond of the abbrevation msec or even msecs. The official abbreviation is ms. Btw., I was wondering, are we kidding ourselves when we display microsecond precision to the user? What accuracy do these measurements have in respect to what they are actually supposed to measure? -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut wrote: Tom Lane writes: Sure it can. You're essentially arguing that DBAs are too dumb to match up matching query and duration log outputs. I don't buy that. I think they'll be analyzing their logs with little Perl scripts anyway, and that consistency of log output format will be worth more to those scripts than sometimes having related items all on one log line. When you're dealing with a large installation, these little Perl scripts become difficult. I've just had to deal with a similar issue with a popular MTA which spreads the relevant log information over several lines. If you're generating 500 MB of log output a day, it becomes a problem. I can imagine. I wasn't sure how I would write Perl code to join things via pid. I am sure it can be done (load into hash), but it wasn't trivial like grep. Peter, any problems with pid wrap-around? I am thinking we need to prepend a wrap count on the front of the pid output for 7.5. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut wrote:
Tom Lane writes:
I would prefer to see the log entries look like
LOG: query: select * from pg_class;
LOG: duration: nn.nnn msec
I'm not fond of the abbrevation msec or even msecs. The official
abbreviation is ms.
Yep. Someone suggested msec in their example, so I used that, but I
like ms better too:
LOG: duration: 0.950 ms; select 1;
LOG: duration: 0.269 ms; set log_min_duration_statement = 1;
Patch attached.
Btw., I was wondering, are we kidding ourselves when we display
microsecond precision to the user? What accuracy do these measurements
have in respect to what they are actually supposed to measure?
Not sure. I think the microsecond stuff is accurate to some degree, but
not sure how much. I think the tick is 10ms, but I thought the timing
was much more accurate than that.
--
Bruce Momjian| http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup.| Newtown Square, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 - 1.210
--- doc/src/sgml/runtime.sgml 5 Oct 2003 14:12:20 -
***
*** 1691,1702
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero (the default)
!disables time-based logging. For example, if you set it
to literal250/literal then all SQL statements that run longer
! than 250ms will be logged. Enabling this
! option can be useful in tracking down unoptimized queries in
! your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
/para
--- 1691,1702
Sets a minimum statement execution time (in milliseconds)
above which a statement will be logged. All SQL statements
that run longer than the time specified will be logged together
! with their actual duration. Setting this to zero will print
! all queries with their durations. Minus-one (the default)
! disables time-based logging. For example, if you set it
to literal250/literal then all SQL statements that run longer
! than 250ms will be logged. Enabling this option can be useful
! in tracking down unoptimized queries in your applications.
Only superusers can increase this or set it to zero if this option
is set to non-zero by the administrator.
/para
Index: src/backend/tcop/postgres.c
===
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 - 1.370
--- src/backend/tcop/postgres.c 5 Oct 2003 14:12:23 -
***
*** 694,700
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement 0)
gettimeofday(start_t, NULL);
if (save_log_statement_stats)
--- 694,700
* because gettimeofday() wasn't called. Similarly,
* log_statement_stats has to be captured once.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
gettimeofday(start_t, NULL);
if (save_log_statement_stats)
***
*** 940,946
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement 0)
{
longusecs;
boolprint_statement;
--- 940,946
* Combine processing here as we need to calculate the query duration
* in both instances.
*/
! if (save_log_duration || save_log_min_duration_statement != -1)
{
longusecs;
boolprint_statement;
***
*** 957,971
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement 0
! usecs =
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian wrote: Btw., I was wondering, are we kidding ourselves when we display microsecond precision to the user? What accuracy do these measurements have in respect to what they are actually supposed to measure? Not sure. I think the microsecond stuff is accurate to some degree, but not sure how much. I think the tick is 10ms, but I thought the timing was much more accurate than that. On my (slow) linux box the apparent time delay between 2 immediately successive calls to gettimeofday() is 3 or 4 microsecs. Presumably the clock tick is something much larger than that - I forget where to look to find that out. I think the real question is what granularity of reporting will be most useful. For the session duration patch I restricted it to 1/100th of a second, and didn't bother rounding the last place there because it wasn't worth it (I thought). For query duration presumably something smaller seems appropriate, but I'm not sure how small. I suspect anything much below a millisec (or at most 100 microsecs) is of comparatively little value. OTOH truncating it is also probably of little value - if you can read 3 or 4 decimal places you can read 6 just as easily - just be aware that the low values have little information value. cheers andrew ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut [EMAIL PROTECTED] writes: When you're dealing with a large installation, these little Perl scripts become difficult. I've just had to deal with a similar issue with a popular MTA which spreads the relevant log information over several lines. If you're generating 500 MB of log output a day, it becomes a problem. True, but it would take really serious revisions of our log output formatting to fix things so that a naive grep will be useful for much of anything. To take just the most obvious limitation in what Bruce is proposing: a grep for duration will yield the duration and the first line of the SQL command. If an installation is in the habit of breaking their SQL into multiple lines, this will be less than useful. Some people like to format their code like this: SELECT a, b, c FROM ... in which case showing just the first line will be quite content-free. There are already similar problems with extracting error information from the logs (and the 7.4 redesign of error formatting has made 'em worse). If we are going to try to design the log output so that you don't need reassembly scripts to link related lines together, then we have got lots bigger problems to fix than log_duration. I'm not convinced it's an appropriate goal at all, though. regards, tom lane ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: Peter, any problems with pid wrap-around? I am thinking we need to prepend a wrap count on the front of the pid output for 7.5. Why? And how would you know when the PIDs have wrapped anyway? The OS already guarantees that no two concurrently running procs have the same PID. That seems sufficient to me. It's conceivable that a PID could be recycled quickly enough that it wasn't obvious from the logs that this was a new backend process and not the same old one, but do you care? (And if you did care, wouldn't you be monitoring log_connections, which would tip you off?) I think this is a red herring. regards, tom lane ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
On Sat, 4 Oct 2003, Tom Lane wrote: Date: Sat, 04 Oct 2003 15:43:34 -0400 From: Tom Lane [EMAIL PROTECTED] To: Bruce Momjian [EMAIL PROTECTED] Cc: Peter Eisentraut [EMAIL PROTECTED], Neil Conway [EMAIL PROTECTED], PostgreSQL Patches [EMAIL PROTECTED] Subject: Re: [PATCHES] fix log_min_duration_statement logic error Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: I would prefer to see the log entries look like LOG: query: select * from pg_class; LOG: duration: nn.nnn msec The problem with two lines is that another log message could get between them. That was true already with log_statement and log_duration as separate operations. People use log_pid to deal with it. Sorry to jump in... the log_pid is NOT ENOUGH where you have more than 3 connections a day (witch is my case) There has been discussion as to have 1 Log file/database where are we on that? Is it dead? Thanks regards, tom lane ---(end of broadcast)--- TIP 9: the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match -- Olivier PRENANT Tel: +33-5-61-50-97-00 (Work) 6, Chemin d'Harraud Turrou +33-5-61-50-97-01 (Fax) 31190 AUTERIVE +33-6-07-63-80-64 (GSM) FRANCE Email: [EMAIL PROTECTED] -- Make your life a dream, make your dream a reality. (St Exupery) ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
That was true already with log_statement and log_duration as separate operations. People use log_pid to deal with it. Sorry to jump in... the log_pid is NOT ENOUGH where you have more than 3 connections a day (witch is my case) log_pid isn't enough, but log_pid + log_connections certainly is. log_connections tells you when a new connection was made, so guessing isn't required. There has been discussion as to have 1 Log file/database where are we on that? Is it dead? Well, this wouldn't help either unless you happen to have several not so active databases that makes for a busy system. signature.asc Description: This is a digitally signed message part
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Peter Eisentraut [EMAIL PROTECTED] writes: When you're dealing with a large installation, these little Perl scripts become difficult. I've just had to deal with a similar issue with a popular MTA which spreads the relevant log information over several lines. If you're generating 500 MB of log output a day, it becomes a problem. True, but it would take really serious revisions of our log output formatting to fix things so that a naive grep will be useful for much of anything. To take just the most obvious limitation in what Bruce is proposing: a grep for duration will yield the duration and the first line of the SQL command. If an installation is in the habit of breaking their SQL into multiple lines, this will be less than useful. Some people like to format their code like this: SELECT a, b, c FROM ... in which case showing just the first line will be quite content-free. It is pretty easy to continue pulling lines after the 'duration' hit to see the full query, perhap using awk, or even grep with a + arg. I just don't see why we should make it harder for folks by splitting it over several lines. For folks that want to use perl, they can use the existing log_* outputs to join by pid and get whatever they want. If you want to call this option an option for dummies that don't want to deal with Perl (and Peter has expressed that it isn't easy), that's fine. Does someone want to show us a Perl script do join lines for this must-requested output? I don't feel like sending it to everyone who needs to find the slow queries in their application. Do you? If you want, we can have vote on it. Frankly, the code was designed and submitted as one line output, and I think a vote will show one-line output as the winner. There are already similar problems with extracting error information from the logs (and the 7.4 redesign of error formatting has made 'em worse). If we are going to try to design the log output so that you don't need reassembly scripts to link related lines together, then we have got lots bigger problems to fix than log_duration. I'm not convinced it's an appropriate goal at all, though. Again, it is cost/benefit --- how many people want easy reporting of queries and their durations. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] fix log_min_duration_statement logic error
On Sun, 5 Oct 2003, Rod Taylor wrote: Date: Sun, 05 Oct 2003 13:05:32 -0400 From: Rod Taylor [EMAIL PROTECTED] To: [EMAIL PROTECTED] Cc: Tom Lane [EMAIL PROTECTED], Bruce Momjian [EMAIL PROTECTED], Peter Eisentraut [EMAIL PROTECTED], Neil Conway [EMAIL PROTECTED], PostgreSQL Patches [EMAIL PROTECTED] Subject: Re: [PATCHES] fix log_min_duration_statement logic error That was true already with log_statement and log_duration as separate operations. People use log_pid to deal with it. Sorry to jump in... the log_pid is NOT ENOUGH where you have more than 3 connections a day (witch is my case) log_pid isn't enough, but log_pid + log_connections certainly is. log_connections tells you when a new connection was made, so guessing isn't required. There has been discussion as to have 1 Log file/database where are we on that? Is it dead? Well, this wouldn't help either unless you happen to have several not so active databases that makes for a busy system. Only that I could give the log file to the customer owning the database(s) that would make my job esier. Also I'd love to see the log_query being settable per database... -- Olivier PRENANT Tel: +33-5-61-50-97-00 (Work) 6, Chemin d'Harraud Turrou +33-5-61-50-97-01 (Fax) 31190 AUTERIVE +33-6-07-63-80-64 (GSM) FRANCE Email: [EMAIL PROTECTED] -- Make your life a dream, make your dream a reality. (St Exupery) ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut [EMAIL PROTECTED] writes: Tom Lane writes: BTW, EXPLAIN ANALYZE puts out Total runtime: 406.53 msec Do you want to make an exception to the string freeze to change this to ms? I just realized, all the things that are sent as a query result instead of an error or notice are not gettext-enabled. I guess we'll have to do without that in this release. So, making the above change does not pose a problem. Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue? regards, tom lane ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Peter Eisentraut [EMAIL PROTECTED] writes: Tom Lane writes: BTW, EXPLAIN ANALYZE puts out Total runtime: 406.53 msec Do you want to make an exception to the string freeze to change this to ms? I just realized, all the things that are sent as a query result instead of an error or notice are not gettext-enabled. I guess we'll have to do without that in this release. So, making the above change does not pose a problem. Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue? I think three is the only reasonable number --- when you are in digits to the right of the decimal, it should be grouped by three. To group by two makes it look like a US dollar amount, and I can't see a rational for two digits. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [PATCHES] fix log_min_duration_statement logic error
[EMAIL PROTECTED] writes: Also I'd love to see the log_query being settable per database... AFAIK you can do that now. regards, tom lane ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian wrote: Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: It is pretty easy to continue pulling lines after the 'duration' hit to see the full query, perhap using awk, or even grep with a + arg. I just don't see why we should make it harder for folks by splitting it over several lines. Somehow I fail to see how that's a consistent position. It is easier than making things split across lines. It is a common request so I want to make it as easy as possible --- that seems consistent. If you can think of a way to make it even easier, please let me know. I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. Also, now that you mention queries output as multiple lines: LOG: duration: 3.938 ms; select * from pg_language; Should we instead convert newlines to \n and output the query as a single line? Do we have lots of other multi-line outputs in the log files? -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. That is exactly my argument. I'll freely admit that it's not a strong point, but I find the claim that the inconsistent formats will be easier to parse to be a much weaker argument, in the absence of any attempt to make them *actually* easier to parse (like really truly one line). [ later ] Should we instead convert newlines to \n and output the query as a single line? That would shore up your position considerably. It needs a little thought as to whether this would induce any confusion, and whether we really care if so. regards, tom lane ---(end of broadcast)--- TIP 9: the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. That is exactly my argument. I'll freely admit that it's not a strong point, but I find the claim that the inconsistent formats will be easier to parse to be a much weaker argument, in the absence of any attempt to make them *actually* easier to parse (like really truly one line). [ later ] Should we instead convert newlines to \n and output the query as a single line? That would shore up your position considerably. It needs a little thought as to whether this would induce any confusion, and whether we really care if so. Good, we are moving forward with something we both like. Let me work up a patch and post it. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PATCHES] fix log_min_duration_statement logic error
I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. I think this is a perfectly good argument. Don't make writing the tools to parse the log more difficult than necessary. Rather than making the log files look nice, lets add a module to PgAdmin that can read it and display it in a user friendly manner (with abilities like sorting queries by execution time!). Should we instead convert newlines to \n and output the query as a single line? Do we have lots of other multi-line outputs in the log files? Please don't. Or if you do, don't data unless you intend to escape special characters (in this case \) at the same time so we can convert it back to the original state. signature.asc Description: This is a digitally signed message part
Re: [PATCHES] fix log_min_duration_statement logic error
Rod Taylor wrote:
-- Start of PGP signed section.
I have not heard from you why we should make it harder (split across two
lines), except for consistency with log_statement and log_duration
outputs.
I think this is a perfectly good argument. Don't make writing the tools
to parse the log more difficult than necessary.
Rather than making the log files look nice, lets add a module to PgAdmin
that can read it and display it in a user friendly manner (with
abilities like sorting queries by execution time!).
Should we instead convert newlines to \n and output the query as a
single line? Do we have lots of other multi-line outputs in the log
files?
Please don't. Or if you do, don't data unless you intend to escape
special characters (in this case \) at the same time so we can convert
it back to the original state.
OK, I coded to convert newline to \n, carriage return to \r, and
backslash to \\. This might cause confusion if you are doing:
INSERT INTO tab VALUES ('\b');
which outputs as:
INSERT INTO tab VALUES ('\\b');
but I see your point that we should be accurate. Actual output is:
LOG: duration: 1.762 ms; insert into ii values ('\\b');
Another example:
LOG: duration: 4.228 ms; select *\nfrom pg_language;
--
Bruce Momjian| http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup.| Newtown Square, Pennsylvania 19073
---(end of broadcast)---
TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I have not heard from you why we should make it harder (split across two lines), except for consistency with log_statement and log_duration outputs. That is exactly my argument. I'll freely admit that it's not a strong point, but I find the claim that the inconsistent formats will be easier to parse to be a much weaker argument, in the absence of any attempt to make them *actually* easier to parse (like really truly one line). [ later ] Should we instead convert newlines to \n and output the query as a single line? That would shore up your position considerably. It needs a little thought as to whether this would induce any confusion, and whether we really care if so. OK, patch attached. It does the single-line log_min_duration_statement, and adds a zero value to always print the duration and statement. I have also added code to convert end-of-line characters to \n and \r, and doubles backslashes. It also makes log_statement print as one line, and shows pg_stat_activity as one line. Without this fix, you get: test= select * from pg_stat_activity; datid | datname | procpid | usesysid | usename | current_query | query_start ---+-+-+--+--+---+--- 17139 | test| 19167 |1 | postgres | | 17139 | test| 19131 |1 | postgres | select * from pg_class, pg_proc; | 2003-10-05 15:14:05.338268-04 New output is: test= select * from pg_stat_activity; datid | datname | procpid | usesysid | usename | current_query | query_start ---+-+-+--+--+---+--- 17139 | test| 20391 |1 | postgres | | 17139 | test| 20344 |1 | postgres | select *\nfrom pg_proc, pg_class; | 2003-10-05 16:25:07.610427-04 (2 rows) -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 Index: doc/src/sgml/runtime.sgml === RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v retrieving revision 1.210 diff -c -c -r1.210 runtime.sgml *** doc/src/sgml/runtime.sgml 3 Oct 2003 19:26:49 - 1.210 --- doc/src/sgml/runtime.sgml 5 Oct 2003 20:26:09 - *** *** 1691,1702 Sets a minimum statement execution time (in milliseconds) above which a statement will be logged. All SQL statements that run longer than the time specified will be logged together ! with their actual duration. Setting this to zero (the default) !disables time-based logging. For example, if you set it to literal250/literal then all SQL statements that run longer ! than 250ms will be logged. Enabling this ! option can be useful in tracking down unoptimized queries in ! your applications. Only superusers can increase this or set it to zero if this option is set to non-zero by the administrator. /para --- 1691,1702 Sets a minimum statement execution time (in milliseconds) above which a statement will be logged. All SQL statements that run longer than the time specified will be logged together ! with their actual duration. Setting this to zero will print ! all queries with their durations. Minus-one (the default) ! disables time-based logging. For example, if you set it to literal250/literal then all SQL statements that run longer ! than 250ms will be logged. Enabling this option can be useful ! in tracking down unoptimized queries in your applications. Only superusers can increase this or set it to zero if this option is set to non-zero by the administrator. /para Index: src/backend/tcop/postgres.c === RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v retrieving revision 1.370 diff -c -c -r1.370 postgres.c *** src/backend/tcop/postgres.c 4 Oct 2003 02:47:04 - 1.370 --- src/backend/tcop/postgres.c 5 Oct 2003 20:26:12 - *** *** 150,156 static void finish_xact_command(void); static void SigHupHandler(SIGNAL_ARGS); static void FloatExceptionHandler(SIGNAL_ARGS); ! /* *routines to obtain user
Re: [PATCHES] fix log_min_duration_statement logic error
have also added code to convert end-of-line characters to \n and \r, and doubles backslashes. It also makes log_statement print as one line, and shows pg_stat_activity as one line. Without this fix, you get: And how does it look with what was originally a fairly readable 30 or 40 line query? signature.asc Description: This is a digitally signed message part
Re: [PATCHES] fix log_min_duration_statement logic error
Rod Taylor wrote: -- Start of PGP signed section. have also added code to convert end-of-line characters to \n and \r, and doubles backslashes. It also makes log_statement print as one line, and shows pg_stat_activity as one line. Without this fix, you get: And how does it look with what was originally a fairly readable 30 or 40 line query? Probably pretty long. I think the pg_stat_activity case really needs the \n because if not the query breaks the table output format. Not sure about log_statement or log_min_duration_statement. Having it be one line makes grep easy, and is probably easier for processing via tools, but reading the log could be harder: LOG: duration: 7.466 ms; select *\nfrom pg_class\nwhere oid = 3 and\nrelname = 'abcd' and\nrelkind = 'r'\norder by relname; The old format output was: LOG: duration: 7.466 ms; select * from pg_class where oid = 3 and relname = 'abcd' and relkind = 'r' order by relname; It is hard to understand how a tool would grab the query from the above log except to look for another TAG: entry and stop there. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 9: the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: Another example: LOG: duration: 4.228 ms; select *\nfrom pg_language; Minor quibble: would it read better as LOG: duration n.nnn ms: query or LOG: duration n.nnn ms for query regards, tom lane ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: It is hard to understand how a tool would grab the query from the above log except to look for another TAG: entry and stop there. That was pretty much the centerpiece of my complaint --- up to now it's been tremendously difficult to parse the PG logs automatically, and I think something along this line would make it much easier. I am inclined to think though that Bruce has done this in the wrong place. If we are going to try to enforce no real newlines inserted as part of logged strings, then it ought to be done at a low level in elog.c where it will apply to *everything* that goes into the log, not just log_statement/log_duration. For example, we presently allow embedded newlines in DETAIL/HINT messages, which is fine for frontend messages but helps to render the log unparsable. Those should be \n-ified too if we are really interested in making the log easy to process. regards, tom lane ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Probably pretty long. I think the pg_stat_activity case really needs the \n because if not the query breaks the table output format. Not I was actually thinking exactly the opposite. pg_stat_activity viewed in pgadmin GUI is going to format the table perfectly fine, but with everthing on one line it will be next to impossible to understand anything complex. I would imagine psql will also be easier to read using human placed \n's rather than random ones at the terminal width. Perhaps the environment I work in isn't the normal case, but usually if I'm trying to track something down, it's the complex 10 table join, multi-subselect report style query that someone in account management just happens to be running but poorly formed. It is hard to understand how a tool would grab the query from the above log except to look for another TAG: entry and stop there. Yup.. Same way you group entries by PID, then reset the PID the next time you see a new connection formed with it. signature.asc Description: This is a digitally signed message part
Re: [PATCHES] fix log_min_duration_statement logic error
Rod Taylor wrote: -- Start of PGP signed section. Probably pretty long. I think the pg_stat_activity case really needs the \n because if not the query breaks the table output format. Not I was actually thinking exactly the opposite. pg_stat_activity viewed in pgadmin GUI is going to format the table perfectly fine, but with everthing on one line it will be next to impossible to understand anything complex. You are right. It is psql that is at fault for causing the \n value to start at the beginning of the next line and not at the proper column on the next line. I will not change the pg_stat_activity values. Tom's idea of doing it in elog is better, of course. I would imagine psql will also be easier to read using human placed \n's rather than random ones at the terminal width. Right. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 5: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faqs/FAQ.html
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Peter Eisentraut [EMAIL PROTECTED] writes: Tom Lane writes: BTW, EXPLAIN ANALYZE puts out Total runtime: 406.53 msec Do you want to make an exception to the string freeze to change this to ms? I just realized, all the things that are sent as a query result instead of an error or notice are not gettext-enabled. I guess we'll have to do without that in this release. So, making the above change does not pose a problem. Okay, I'll make that change. Any opinions about the 2-vs-3-digit issue? I just committed a fix so psql \timing shows three digits: test= \timing Timing is on. test= select 1; ?column? -- 1 (1 row) Time: 1.306 ms -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ? psql Index: common.c === RCS file: /cvsroot/pgsql-server/src/bin/psql/common.c,v retrieving revision 1.74 diff -c -c -r1.74 common.c *** common.c16 Sep 2003 17:59:02 - 1.74 --- common.c5 Oct 2003 22:31:26 - *** *** 550,556 /* Possible microtiming output */ if (pset.timing success) ! printf(gettext(Time: %.2f ms\n), DIFF_MSEC(after, before)); return success; } --- 550,556 /* Possible microtiming output */ if (pset.timing success) ! printf(gettext(Time: %.3f ms\n), DIFF_MSEC(after, before)); return success; } ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
The problem with two lines is that another log message could get between them. I agree milliseconds makes more sense for output. That's not a huge problem. I've run our servers like that for ages, and there's not really any time when a human can't tell what's going on. You can also turn on PID logging as well. (Should that even be on by default? Chris ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian writes: Thanks Peter. Patch attached. I added (secs) to the ouput: LOG: duration(secs): 0.000257 LOG: duration(secs): 0.000754 LOG: duration(secs): 0.008115 select * from pg_class; I think the units typically go after the number. -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] fix log_min_duration_statement logic error
Peter Eisentraut [EMAIL PROTECTED] writes: Bruce Momjian writes: LOG: duration(secs): 0.000257 LOG: duration(secs): 0.000754 LOG: duration(secs): 0.008115 select * from pg_class; I think the units typically go after the number. In any case, this is unnecessarily incompatible with everything else. EXPLAIN and psql's \timing show query durations in milliseconds. And isn't log_min_duration_statement itself measured in milliseconds? I would prefer to see the log entries look like LOG: query: select * from pg_class; LOG: duration: nn.nnn msec in all cases, rather than moving information around depending on which combination of switches happens to have caused the log entries to be generated. Am willing to fix the code to make this happen. regards, tom lane ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: I would prefer to see the log entries look like LOG: query: select * from pg_class; LOG: duration: nn.nnn msec The problem with two lines is that another log message could get between them. That was true already with log_statement and log_duration as separate operations. People use log_pid to deal with it. regards, tom lane ---(end of broadcast)--- TIP 9: the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: Tom Lane wrote: I would prefer to see the log entries look like LOG: query: select * from pg_class; LOG: duration: nn.nnn msec The problem with two lines is that another log message could get between them. That was true already with log_statement and log_duration as separate operations. People use log_pid to deal with it. Attached are some emails I sent while we were discussing this feature in March. The idea was for the parameter to show query and duration --- a combination that is asked for frequently and easily grep'ed, unlike joining on pid, which because of pid wrap-around, isn't even fool-proof. One thing that isn't implemented in current CVS is to allow 0 to always print the duration and query (-1 disables it and is the default). I can see that being _very_ valuable, and used enough to warrant the fact that it isn't orthoginal (we already have log_statement). The reason we needed to do it this way was so we could print the statement _after_ it completes so we could include the duration. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 From pgman Wed Feb 12 15:03:03 2003 Subject: Re: [HACKERS] log_duration In-Reply-To: [EMAIL PROTECTED] To: Greg Stark [EMAIL PROTECTED] Date: Wed, 12 Feb 2003 16:49:58 -0500 (EST) cc: [EMAIL PROTECTED] X-Mailer: ELM [version 2.4ME+ PL99 (25)] MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=US-ASCII Content-Length: 3288 Status: OR Greg Stark wrote: Tom Lane [EMAIL PROTECTED] writes: Christopher Kings-Lynne [EMAIL PROTECTED] writes: Looking at the log_duration postgresql.conf option. How about adding an option log_duration_min which is a value in milliseconds that is the minimum time a query must run for before being logged. Fine with me --- but you'll need to add more logic than that. Right now, log_duration *only* causes the query duration to be printed out; if you ain't got log_statement on, you're in the dark as to what the query itself was. You'll need to add some code to print the query (the log_min_error_statement logic might be a useful source of inspiration). Not sure how this should interact with the case where log_duration is set and the min-duration isn't. But maybe that case is silly, and we should just redefine log_duration as a minimum runtime that causes the query *and* its runtime to be printed to the log. Tom is right here. log_duration _just_ prints the duration, so we would need to basically create a merged param that does log_duration and log_statement and have it activate only if the statement takes more than X milliseconds, something like log_long_statement, or something like that. Here are the log_* params we have: log_connections = false log_hostname = false log_source_port = false log_pid = false log_statement = false log_duration = false log_timestamp = false Basically, log_pid pulls them all together. Without that, you don't have any way to pull together individual lines in the log, and with pid wraparound, you can't even do that 100%. I wonder if we should put a number before the pid and increment it on every pid wraparound. One nice thing is that each element is orthoginal. But, for the functionality desired, we have to merge log_statement and log_duration and have it print for statements taking over X milliseconds. I have no problem adding it, but it has to be clear it isn't orthoginal but is a conditional combination of two other parameters. Is it even guaranteed to be properly ordered on a busy server with multiple processors anyways? One option is to have log_query output an identifier with the query such as a hash of the query or the pointer value for the plan, suppressing duplicates. Then log_duration prints the identifier with the duration. This means on a busy server running lots of prepared queries you would see a whole bunch of queries on startup, then hopefully no durations. Any durations printed could cause alarms to go off. To find the query you grep the logs for the identifier in the duration message. Actually, log_pid is the proper way to do this. You can then add log connections, and get a full snapshot of what is happening for that session. This only really works if you're using prepared queries everywhere. But in the long run that will be the case for OLTP systems, which is where log_duration is really useful. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: The reason we needed to do it this way was so we could print the statement _after_ it completes so we could include the duration. The behavior I had in mind was to dump the statement at the end of the query if (a) the duration needs to be printed and (b) the statement wasn't already dumped at the start --- ie, log_statement was not on at the start. The historical behavior of log_min_error_statement has been to make two separate log entries: the failing query and the error. This has worked well enough AFAIK; why not keep that behavior for log_min_duration? I think separate entries work for log_min_error_statement because the error string and query are both long, and you can pretty much guess which error goes with which query, and you are looking at errors, which are pretty rare events, hopefully. I think they fit pretty nicely on one line, and lot of folks want that information. I realize it looks like bloatware because it duplicates some existing functionality, but I think it is a combination of duration and statement output that can't be done easily separately. Also, I don't see us combining any other log_* operations: #log_connections = false #log_duration = false #log_pid = false #log_statement = false #log_timestamp = false #log_hostname = false #log_source_port = false BTW, there's a separate set of problems that have yet to be addressed, which is how any of these logging options apply for V3-protocol query operations. The existing code only seems to work for the old-style query path. You mean how are they passed to the client? I assumed that would work for pre-V3 clients. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Bruce Momjian [EMAIL PROTECTED] writes: I think they fit pretty nicely on one line, and lot of folks want that information. I realize it looks like bloatware because it duplicates some existing functionality, but I think it is a combination of duration and statement output that can't be done easily separately. Sure it can. You're essentially arguing that DBAs are too dumb to match up matching query and duration log outputs. I don't buy that. I think they'll be analyzing their logs with little Perl scripts anyway, and that consistency of log output format will be worth more to those scripts than sometimes having related items all on one log line. Yes, I am arguing that we shouldn't make people jump through Perl hoops to get a statement/duration line in their log files. I think it is asked for enough that a nice printed line will help them. If we already have the parameter, why not make it easy. If they are using Perl, they can already use log_statement and log_duration to print only queries taking over a certain amount of time. BTW, there's a separate set of problems that have yet to be addressed, which is how any of these logging options apply for V3-protocol query operations. The existing code only seems to work for the old-style query path. You mean how are they passed to the client? I assumed that would work for pre-V3 clients. No, I mean the functionality isn't in the extended-query code path at all, and it's not immediately clear where to insert it (eg, which steps of parse/bind/execute do what logging, or where you measure duration). I assume it would be all executor stuff, but I see what you mean that the perpare isn't going through the normal query path. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 7: don't forget to increase your free space map settings
Re: [PATCHES] fix log_min_duration_statement logic error
Bruce Momjian writes: I think there should be just one duration: nnn log entry, printed if either condition holds. Done. Now, if I have log_statement and log_duration on, it logs each statement twice. The documentation says this: log_duration (boolean) Causes the duration of every completed statement to be logged. To use this option, enable log_statement and log_pid so you can link the statement to the duration using the process ID. This needs more thought. Also, please put units on all numbers. -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 6: Have you searched our list archives? http://archives.postgresql.org
Re: [PATCHES] fix log_min_duration_statement logic error
Thanks Peter. Patch attached. I added (secs) to the ouput:
LOG: duration(secs): 0.000257
LOG: duration(secs): 0.000754
LOG: duration(secs): 0.008115 select * from pg_class;
---
Peter Eisentraut wrote:
Bruce Momjian writes:
I think there should be just one duration: nnn log entry, printed if
either condition holds.
Done.
Now, if I have log_statement and log_duration on, it logs each statement
twice. The documentation says this:
log_duration (boolean)
Causes the duration of every completed statement to be logged. To use
this option, enable log_statement and log_pid so you can link the
statement to the duration using the process ID.
This needs more thought.
Also, please put units on all numbers.
--
Peter Eisentraut [EMAIL PROTECTED]
--
Bruce Momjian| http://candle.pha.pa.us
[EMAIL PROTECTED] | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup.| Newtown Square, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.369
diff -c -c -r1.369 postgres.c
*** src/backend/tcop/postgres.c 2 Oct 2003 06:34:04 - 1.369
--- src/backend/tcop/postgres.c 4 Oct 2003 02:45:50 -
***
*** 943,948
--- 943,949
if (save_log_duration || save_log_min_duration_statement 0)
{
longusecs;
+ boolprint_statement;
gettimeofday(stop_t, NULL);
if (stop_t.tv_usec start_t.tv_usec)
***
*** 956,969
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! if (save_log_duration ||
! (save_log_min_duration_statement 0
!usecs = save_log_min_duration_statement * 1000))
ereport(LOG,
! (errmsg(duration: %ld.%06ld %s,
(long) (stop_t.tv_sec -
start_t.tv_sec),
(long) (stop_t.tv_usec -
start_t.tv_usec),
! query_string)));
}
if (save_log_statement_stats)
--- 957,972
* Output a duration_statement to the log if the query has exceeded
* the min duration, or if we are to print all durations.
*/
! print_statement = (save_log_min_duration_statement 0
! usecs =
save_log_min_duration_statement * 1000);
!
! if (save_log_duration || print_statement)
ereport(LOG,
! (errmsg(duration(secs): %ld.%06ld%s%s,
(long) (stop_t.tv_sec -
start_t.tv_sec),
(long) (stop_t.tv_usec -
start_t.tv_usec),
! print_statement ? : ,
! print_statement ? query_string
: )));
}
if (save_log_statement_stats)
---(end of broadcast)---
TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane wrote: Neil Conway [EMAIL PROTECTED] writes: I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. I think there should be just one duration: nnn log entry, printed if either condition holds. Done. -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Tom Lane writes: Neil Conway [EMAIL PROTECTED] writes: I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. I think there should be just one duration: nnn log entry, printed if either condition holds. Is anyone going to take care of this? -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [PATCHES] fix log_min_duration_statement logic error
Yes, I will. --- Peter Eisentraut wrote: Tom Lane writes: Neil Conway [EMAIL PROTECTED] writes: I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. I think there should be just one duration: nnn log entry, printed if either condition holds. Is anyone going to take care of this? -- Peter Eisentraut [EMAIL PROTECTED] ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED] -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster
Re: [PATCHES] fix log_min_duration_statement logic error
Your patch has been added to the PostgreSQL unapplied patches list at: http://momjian.postgresql.org/cgi-bin/pgpatches I will try to apply it within the next 48 hours. --- Neil Conway wrote: This patch fixes an obvious bug in the should I print the duration of this query? logic in postgres.c I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. -Neil [ Attachment, skipping... ] ---(end of broadcast)--- TIP 4: Don't 'kill -9' the postmaster -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 2: you can get off all lists at once with the unregister command (send unregister YourEmailAddressHere to [EMAIL PROTECTED])
Re: [PATCHES] fix log_min_duration_statement logic error
I think there should be just one duration: nnn log entry, printed if either condition holds. Your patch has been added to the PostgreSQL unapplied patches list at: http://momjian.postgresql.org/cgi-bin/pgpatches I will try to apply it within the next 48 hours. --- Tom Lane wrote: Neil Conway [EMAIL PROTECTED] writes: I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. I think there should be just one duration: nnn log entry, printed if either condition holds. regards, tom lane ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly -- Bruce Momjian| http://candle.pha.pa.us [EMAIL PROTECTED] | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup.| Newtown Square, Pennsylvania 19073 ---(end of broadcast)--- TIP 1: subscribe and unsubscribe commands go to [EMAIL PROTECTED]
Re: [PATCHES] fix log_min_duration_statement logic error
Neil Conway [EMAIL PROTECTED] writes: I also don't particularly like the format of the log message (for one thing, the duration_statement prefix in the log message shouldn't include an underscore, it's not a variable or anything -- and the case can be made that if we printed the duration because log_duration is set, we don't need to print it again if the duration of the query exceeded log_min_duration_statement), but I haven't changed it. I think there should be just one duration: nnn log entry, printed if either condition holds. regards, tom lane ---(end of broadcast)--- TIP 3: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
