Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Jeff Davis wrote: > On Mon, 2015-09-07 at 18:28 -0300, Alvaro Herrera wrote: > > I think the extra ugliness is warranted, since it's not THAT much > > additional ugliness, and not doing it could be considered a regression; > > apparently strftime can be slower even than snprintf, so doing it twice > > per log message might be excessive overhead. > > Patch attached. Please take a quick look. Looks good. -- Álvaro Herrerahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Mon, 2015-09-07 at 18:28 -0300, Alvaro Herrera wrote: > I noticed %t, but I don't think we care since the precision is so poor. > Making m and n work in unison seems enough. I think it would be > reasonably simple to handle %t in the same way, but I'm not sure we > care. OK. > I think the extra ugliness is warranted, since it's not THAT much > additional ugliness, and not doing it could be considered a regression; > apparently strftime can be slower even than snprintf, so doing it twice > per log message might be excessive overhead. Patch attached. Please take a quick look. Regards, Jeff Davis *** a/src/backend/utils/error/elog.c --- b/src/backend/utils/error/elog.c *** *** 143,152 static int errordata_stack_depth = -1; /* index of topmost active frame */ static int recursion_depth = 0; /* to detect actual recursion */ ! /* buffers for formatted timestamps that might be used by both ! * log_line_prefix and csv logs. */ #define FORMATTED_TS_LEN 128 static char formatted_start_time[FORMATTED_TS_LEN]; static char formatted_log_time[FORMATTED_TS_LEN]; --- 143,156 static int recursion_depth = 0; /* to detect actual recursion */ ! /* ! * Saved timeval and buffers for formatted timestamps that might be used by ! * both log_line_prefix and csv logs. */ + static struct timeval saved_timeval; + static boolsaved_timeval_set = false; + #define FORMATTED_TS_LEN 128 static char formatted_start_time[FORMATTED_TS_LEN]; static char formatted_log_time[FORMATTED_TS_LEN]; *** *** 2195,2206 write_console(const char *line, int len) static void setup_formatted_log_time(void) { - struct timeval tv; pg_time_t stamp_time; char msbuf[8]; ! gettimeofday(&tv, NULL); ! stamp_time = (pg_time_t) tv.tv_sec; /* * Note: we expect that guc.c will ensure that log_timezone is set up (at --- 2199,2214 static void setup_formatted_log_time(void) { pg_time_t stamp_time; char msbuf[8]; ! if (!saved_timeval_set) ! { ! gettimeofday(&saved_timeval, NULL); ! saved_timeval_set = true; ! } ! ! stamp_time = (pg_time_t) saved_timeval.tv_sec; /* * Note: we expect that guc.c will ensure that log_timezone is set up (at *** *** 2213,2219 setup_formatted_log_time(void) pg_localtime(&stamp_time, log_timezone)); /* 'paste' milliseconds into place... */ ! sprintf(msbuf, ".%03d", (int) (tv.tv_usec / 1000)); memcpy(formatted_log_time + 19, msbuf, 4); } --- 2221,2227 pg_localtime(&stamp_time, log_timezone)); /* 'paste' milliseconds into place... */ ! sprintf(msbuf, ".%03d", (int) (saved_timeval.tv_usec / 1000)); memcpy(formatted_log_time + 19, msbuf, 4); } *** *** 2440,2450 log_line_prefix(StringInfo buf, ErrorData *edata) break; case 'n': { - struct timeval tv; char strfbuf[128]; ! gettimeofday(&tv, NULL); ! sprintf(strfbuf, "%ld.%03d", tv.tv_sec, (int)(tv.tv_usec / 1000)); if (padding != 0) appendStringInfo(buf, "%*s", padding, strfbuf); --- 2448,2463 break; case 'n': { char strfbuf[128]; ! if (!saved_timeval_set) ! { ! gettimeofday(&saved_timeval, NULL); ! saved_timeval_set = true; ! } ! ! sprintf(strfbuf, "%ld.%03d", saved_timeval.tv_sec, ! (int)(saved_timeval.tv_usec / 1000)); if (padding != 0) appendStringInfo(buf, "%*s", padding, strfbuf); *** *** 2825,2830 send_message_to_server_log(ErrorData *edata) --- 2838,2844 initStringInfo(&buf); + saved_timeval_set = false; formatted_log_time[0] = '\0'; log_line_prefix(&buf, edata); -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Jeff Davis wrote: > > I wonder about this separate gettimeofday() call. We already have > > formatted_log_time which is used for CSV logs and freeform log lines > > (stderr/syslog); if we introduce a separate gettimeofday() call here, > > and the user has %n in freeform log and CSV logging is active, the > > timings will diverge occasionally. > > > > Maybe I'm worrying over nothing, because really what use case is there > > for having the two log formats enabled at the same time? Yet somebody > > went some lengths to ensure they are consistent; I think we should do > > likewise here. > > We now have three time-related options[1]: t, m, and n; and they each > acquire the time independently. Are you suggesting that we make all > three consistent, or only m and n? I noticed %t, but I don't think we care since the precision is so poor. Making m and n work in unison seems enough. I think it would be reasonably simple to handle %t in the same way, but I'm not sure we care. (TBH I question that %t has any usefulness at all. Maybe we should phase it out ...) > The cleanest fix would be for the global variable to only hold the > timeval, and then format it once for the CSV log (always 'm' format) and > once for the regular log ('m', 'n', or 't'). If the regular log uses > 'm', that would be some wasted cycles formatting it the same way twice. > Is it worth a little extra ugliness to cache both the timeval and the > formatted string? I think the extra ugliness is warranted, since it's not THAT much additional ugliness, and not doing it could be considered a regression; apparently strftime can be slower even than snprintf, so doing it twice per log message might be excessive overhead. -- Álvaro Herrerahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
> I wonder about this separate gettimeofday() call. We already have > formatted_log_time which is used for CSV logs and freeform log lines > (stderr/syslog); if we introduce a separate gettimeofday() call here, > and the user has %n in freeform log and CSV logging is active, the > timings will diverge occasionally. > > Maybe I'm worrying over nothing, because really what use case is there > for having the two log formats enabled at the same time? Yet somebody > went some lengths to ensure they are consistent; I think we should do > likewise here. We now have three time-related options[1]: t, m, and n; and they each acquire the time independently. Are you suggesting that we make all three consistent, or only m and n? The cleanest fix would be for the global variable to only hold the timeval, and then format it once for the CSV log (always 'm' format) and once for the regular log ('m', 'n', or 't'). If the regular log uses 'm', that would be some wasted cycles formatting it the same way twice. Is it worth a little extra ugliness to cache both the timeval and the formatted string? Regards, Jeff Davis [1] As of minutes ago, after I missed your message by a few minutes. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Mon, 2015-09-07 at 17:47 -0300, Alvaro Herrera wrote: > Jeff Davis wrote: > > On Sun, 2015-03-22 at 19:47 +0100, Andres Freund wrote: > > > On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: > > > > from time to time I need to correlate PostgreSQL logs to other logs, > > > > containing numeric timestamps - a prime example of that is pgbench. With > > > > %t and %m that's not quite trivial, because of timezones etc. > > > > > > I have a hard time seing this is sufficient cause for adding more format > > > codes. They're not free runtime and documentation wise. -0.5 from me. > > > > I am about to commit this patch (the one that adds a single extra > > option). Although nothing is free, the cost seems very low, and at least > > three people have expressed interest in this patch. > > Did you see my message at > http://www.postgresql.org/message-id/20150907192719.GS2912@alvherre.pgsql ? I guess we were looking at this at the same time, and I missed your message and committed it. I will investigate now. Regards, Jeff Davis -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Jeff Davis wrote: > On Sun, 2015-03-22 at 19:47 +0100, Andres Freund wrote: > > On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: > > > from time to time I need to correlate PostgreSQL logs to other logs, > > > containing numeric timestamps - a prime example of that is pgbench. With > > > %t and %m that's not quite trivial, because of timezones etc. > > > > I have a hard time seing this is sufficient cause for adding more format > > codes. They're not free runtime and documentation wise. -0.5 from me. > > I am about to commit this patch (the one that adds a single extra > option). Although nothing is free, the cost seems very low, and at least > three people have expressed interest in this patch. Did you see my message at http://www.postgresql.org/message-id/20150907192719.GS2912@alvherre.pgsql ? -- Álvaro Herrerahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Sun, 2015-03-22 at 19:47 +0100, Andres Freund wrote: > On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: > > from time to time I need to correlate PostgreSQL logs to other logs, > > containing numeric timestamps - a prime example of that is pgbench. With > > %t and %m that's not quite trivial, because of timezones etc. > > I have a hard time seing this is sufficient cause for adding more format > codes. They're not free runtime and documentation wise. -0.5 from me. I am about to commit this patch (the one that adds a single extra option). Although nothing is free, the cost seems very low, and at least three people have expressed interest in this patch. What tips the balance is that we expose the unix epoch in the pgbench logs, as Tomas points out. Regards, Jeff Davis -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
> + case 'n': > + { > + struct timeval tv; > + charstrfbuf[128]; > + > + gettimeofday(&tv, NULL); > + sprintf(strfbuf, "%ld.%03d", tv.tv_sec, > (int)(tv.tv_usec / 1000)); > + > + if (padding != 0) > + appendStringInfo(buf, "%*s", > padding, strfbuf); > + else > + appendStringInfoString(buf, > strfbuf); > + } > + break; I wonder about this separate gettimeofday() call. We already have formatted_log_time which is used for CSV logs and freeform log lines (stderr/syslog); if we introduce a separate gettimeofday() call here, and the user has %n in freeform log and CSV logging is active, the timings will diverge occasionally. Maybe I'm worrying over nothing, because really what use case is there for having the two log formats enabled at the same time? Yet somebody went some lengths to ensure they are consistent; I think we should do likewise here. I'm happy to be outvoted on this, so consider this a -0.5 for this particular implementation. -- Álvaro Herrerahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 08/23/2015 09:28 AM, Fabien COELHO wrote: 1) fix the docs (explicitly say that it's a Unix epoch) I would add the word "numeric" in front of timestamp both in the doc and in the postgresql.conf.sample, as it justifies the chosen %n. I think we're already using 'unix epoch' in the docs without explicitly stating that it's a numeric value, so I don't think we should use it here as it'd be inconsistent. The point was to justify the choice of 'n' somehow. 2) handle 'padding' properly Hmmm, I'm not entirely sure how exactly the padding is supposed to work (IIRC I've never used it), and I thought it behaved correctly. But maybe not - I think the safest thing is copy what 't' does, so I've done that in attached v3 of the patch. Ok. Version 3 applies and compiles, and padding now works as expected. Here is a v4 that I also tested, and where I just removed a spurious '.' in the millisecond format. Thanks for spotting that. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
1) fix the docs (explicitly say that it's a Unix epoch) I would add the word "numeric" in front of timestamp both in the doc and in the postgresql.conf.sample, as it justifies the chosen %n. I think we're already using 'unix epoch' in the docs without explicitly stating that it's a numeric value, so I don't think we should use it here as it'd be inconsistent. The point was to justify the choice of 'n' somehow. 2) handle 'padding' properly Hmmm, I'm not entirely sure how exactly the padding is supposed to work (IIRC I've never used it), and I thought it behaved correctly. But maybe not - I think the safest thing is copy what 't' does, so I've done that in attached v3 of the patch. Ok. Version 3 applies and compiles, and padding now works as expected. Here is a v4 that I also tested, and where I just removed a spurious '.' in the millisecond format. -- Fabien.diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e3dc23b..3ced399 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -4630,6 +4630,11 @@ local0.*/var/log/postgresql no + %n + Time stamp with milliseconds (as a Unix epoch) + no + + %i Command tag: type of session's current command yes diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 088c714..9114c55 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -2438,6 +2438,20 @@ log_line_prefix(StringInfo buf, ErrorData *edata) appendStringInfoString(buf, strfbuf); } break; + case 'n': +{ + struct timeval tv; + char strfbuf[128]; + + gettimeofday(&tv, NULL); + sprintf(strfbuf, "%ld.%03d", tv.tv_sec, (int)(tv.tv_usec / 1000)); + + if (padding != 0) + appendStringInfo(buf, "%*s", padding, strfbuf); + else + appendStringInfoString(buf, strfbuf); +} +break; case 's': if (formatted_start_time[0] == '\0') setup_formatted_start_time(); diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 695a88f..c33e585 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -425,6 +425,7 @@ # %p = process ID # %t = timestamp without milliseconds # %m = timestamp with milliseconds + # %n = timestamp with milliseconds (as a Unix epoch) # %i = command tag # %e = SQL state # %c = session ID -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 08/22/2015 09:54 PM, Fabien COELHO wrote: Hello Tomas, Review of v2: attached is a v2 of the patch, reworked based on the comments. The patch applies cleanly to head, it compiles, I tested it and it mostly work as expected, see below. 1) fix the docs (explicitly say that it's a Unix epoch) I would add the word "numeric" in front of timestamp both in the doc and in the postgresql.conf.sample, as it justifies the chosen %n. I think we're already using 'unix epoch' in the docs without explicitly stating that it's a numeric value, so I don't think we should use it here as it'd be inconsistent. 2) handle 'padding' properly I tried that without success. ISTM that what is padded is the empty string, and the timestamp is just printed on its own without padding afterwards. I think that it should use a string buffer and then used the padding on the string, as case 'c' or 't' for instance. Hmmm, I'm not entirely sure how exactly the padding is supposed to work (IIRC I've never used it), and I thought it behaved correctly. But maybe not - I think the safest thing is copy what 't' does, so I've done that in attached v3 of the patch. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e900dcc..8328733 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -4630,6 +4630,11 @@ local0.*/var/log/postgresql no + %n + Time stamp with milliseconds (as a Unix epoch) + no + + %i Command tag: type of session's current command yes diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 088c714..80ffdbd 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -2438,6 +2438,20 @@ log_line_prefix(StringInfo buf, ErrorData *edata) appendStringInfoString(buf, strfbuf); } break; + case 'n': +{ + struct timeval tv; + char strfbuf[128]; + + gettimeofday(&tv, NULL); + sprintf(strfbuf, "%ld.%.03d", tv.tv_sec, (int)(tv.tv_usec / 1000)); + + if (padding != 0) + appendStringInfo(buf, "%*s", padding, strfbuf); + else + appendStringInfoString(buf, strfbuf); +} +break; case 's': if (formatted_start_time[0] == '\0') setup_formatted_start_time(); diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index e5d275d..34abd17 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -425,6 +425,7 @@ # %p = process ID # %t = timestamp without milliseconds # %m = timestamp with milliseconds + # %n = timestamp with milliseconds (as a Unix epoch) # %i = command tag # %e = SQL state # %c = session ID -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Hello Tomas, Review of v2: attached is a v2 of the patch, reworked based on the comments. The patch applies cleanly to head, it compiles, I tested it and it mostly work as expected, see below. 1) fix the docs (explicitly say that it's a Unix epoch) I would add the word "numeric" in front of timestamp both in the doc and in the postgresql.conf.sample, as it justifies the chosen %n. 2) handle 'padding' properly I tried that without success. ISTM that what is padded is the empty string, and the timestamp is just printed on its own without padding afterwards. I think that it should use a string buffer and then used the padding on the string, as case 'c' or 't' for instance. 3) get rid of timestamp_str - use appendString* methods directly See above, I'm afraid it is necessary for padding, because there are two formatted fields. 4) support just the "with milliseconds" using '%n' escape sequence Ok. All those changes are quite trivial. The only annoying bit is that both '%u' and '%e' are already used, so none of the obvious choices for 'Unix Epoch' are available. So I simply took (%m+1) which is %n. It stands for "numeric" as well, so I think it is quite nice. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Hi all, attached is a v2 of the patch, reworked based on the comments. 1) fix the docs (explicitly say that it's a Unix epoch) 2) handle 'padding' properly 3) get rid of timestamp_str - use appendString* methods directly 4) support just the "with milliseconds" using '%n' escape sequence All those changes are quite trivial. The only annoying bit is that both '%u' and '%e' are already used, so none of the obvious choices for 'Unix Epoch' are available. So I simply took (%m+1) which is %n. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index e900dcc..8328733 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -4630,6 +4630,11 @@ local0.*/var/log/postgresql no + %n + Time stamp with milliseconds (as a Unix epoch) + no + + %i Command tag: type of session's current command yes diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 088c714..4520b9f 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -2438,6 +2438,18 @@ log_line_prefix(StringInfo buf, ErrorData *edata) appendStringInfoString(buf, strfbuf); } break; + case 'n': +{ + struct timeval tv; + gettimeofday(&tv, NULL); + + if (padding != 0) + appendStringInfo(buf, "%*s", padding, ""); + + appendStringInfo(buf, "%ld.%.03d", tv.tv_sec, + (int)(tv.tv_usec / 1000)); +} +break; case 's': if (formatted_start_time[0] == '\0') setup_formatted_start_time(); diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index e5d275d..34abd17 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -425,6 +425,7 @@ # %p = process ID # %t = timestamp without milliseconds # %m = timestamp with milliseconds + # %n = timestamp with milliseconds (as a Unix epoch) # %i = command tag # %e = SQL state # %c = session ID -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Hi, On 08/22/2015 08:39 AM, Fabien COELHO wrote: Hello Tomas, from time to time I need to correlate PostgreSQL logs to other logs, containing numeric timestamps - a prime example of that is pgbench. With %t and %m that's not quite trivial, because of timezones etc. I propose adding two new log_line_prefix escape sequences - %T and %M, doing the same thing as %t and %m, but formatting the value as a number. Patch attached, I'll add it to CF 2015-06. Are you planing to update this patch? I was wanting to use it for some tests and figured out that it had stayed as a proposal, too bad. I would suggest to maybe follow Tom's %u idea and fix the implementation details wrt to comments received? Yes, I plan to update it according to those comments. regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Hello Tomas, from time to time I need to correlate PostgreSQL logs to other logs, containing numeric timestamps - a prime example of that is pgbench. With %t and %m that's not quite trivial, because of timezones etc. I propose adding two new log_line_prefix escape sequences - %T and %M, doing the same thing as %t and %m, but formatting the value as a number. Patch attached, I'll add it to CF 2015-06. Are you planing to update this patch? I was wanting to use it for some tests and figured out that it had stayed as a proposal, too bad. I would suggest to maybe follow Tom's %u idea and fix the implementation details wrt to comments received? It seems to me that always having milliseconds "123456789.012" would be fine, it can easily be filtered out if not necessary or would be there if useful, so maybe just one more format is enough. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 23.3.2015 23:02, Jim Nasby wrote: > On 3/22/15 2:59 PM, Tomas Vondra wrote: >> On 22.3.2015 20:25, Fabien COELHO wrote: >> >>> I guess Tomas put 2 formats because there was 2 time formats >>> to begin with, but truncating/rouding if someone really wants >>> seconds is quite easy. >> >> Yes, that's why I added two - to reflect %t and %m. I'm OK with >> using just one of them - I don't really care for the milliseconds >> at this moment, but I'd probably choose that option. > > I assume we're using milli instead of micro because that's what > everyone else does? It seems odd since we natively support > microseconds, but I guess if milliseconds is more normal for logging > that's OK. That's because %m is using milliseconds. I don't think microseconds are really useful here ... > FWIW, I don't see a problem with both %T and %M (whatever M ends up > meaning), but I don't really care either way. Same here. -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 3/22/15 2:59 PM, Tomas Vondra wrote: On 22.3.2015 20:25, Fabien COELHO wrote: > >>>The proposed format is much simpler to manage in a script, and if you're >>>interested in runtime, its formatting would be less expensive than %t >>>and >>>%m. >> >>Maybe, but do we really need two? How about just %M? > >I guess Tomas put 2 formats because there was 2 time formats to >begin with, but truncating/rouding if someone really wants seconds is >quite easy. Yes, that's why I added two - to reflect %t and %m. I'm OK with using just one of them - I don't really care for the milliseconds at this moment, but I'd probably choose that option. I assume we're using milli instead of micro because that's what everyone else does? It seems odd since we natively support microseconds, but I guess if milliseconds is more normal for logging that's OK. FWIW, I don't see a problem with both %T and %M (whatever M ends up meaning), but I don't really care either way. -- Jim Nasby, Data Architect, Blue Treble Consulting Data in Trouble? Get it in Treble! http://BlueTreble.com -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
The proposed format is much simpler to manage in a script, and if you're interested in runtime, its formatting would be less expensive than %t and %m. Maybe, but do we really need two? How about just %M? I guess Tomas put 2 formats because there was 2 time formats to begin with, but truncating/rouding if someone really wants seconds is quite easy. Also, having just one would open the door to calling it something like %u (for Unix timestamp), I guess that is okay as well. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22.3.2015 20:25, Fabien COELHO wrote: > >>> The proposed format is much simpler to manage in a script, and if you're >>> interested in runtime, its formatting would be less expensive than %t >>> and >>> %m. >> >> Maybe, but do we really need two? How about just %M? > > I guess Tomas put 2 formats because there was 2 time formats to > begin with, but truncating/rouding if someone really wants seconds is > quite easy. Yes, that's why I added two - to reflect %t and %m. I'm OK with using just one of them - I don't really care for the milliseconds at this moment, but I'd probably choose that option. >> Also, having just one would open the door to calling it something >> like %u (for Unix timestamp), > > I guess that is okay as well. Whatever, I don't really care. It's slightly confusing because unix timestams are usually integers, but IMHO that's minor difference. -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22.3.2015 19:45, Fabien COELHO wrote: > >>> I'm not sure that the "." in "%.03d" is useful. ISTM that it is used for >>> floatting point formatting, but is not needed with integers. >> >> It is needed for integers, because you need to make sure 1 millisecond >> is formatted as .001 and not .1. > > ISTM that the "03" does that on its own: > > sh> printf "%03d\n" 0 1 2 > 000 > 001 > 002 Oh, right - one dot too many. Thanks, will fix that. -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
[oops, stalled because of wrong From, resending just to the list] On Sun, 22 Mar 2015, Tom Lane wrote: The proposed format is much simpler to manage in a script, and if you're interested in runtime, its formatting would be less expensive than %t and %m. Maybe, but do we really need two? How about just %M? Yep, truncating or rounding if needed is quite easy. Also, having just one would open the door to calling it something like %u (for Unix timestamp), Should be ok as well. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Sat, Mar 21, 2015 at 4:47 PM, Tomas Vondra wrote: > Hi, > > from time to time I need to correlate PostgreSQL logs to other logs, > containing numeric timestamps - a prime example of that is pgbench. With > %t and %m that's not quite trivial, because of timezones etc. > > I propose adding two new log_line_prefix escape sequences - %T and %M, > doing the same thing as %t and %m, but formatting the value as a number. > > Patch attached, I'll add it to CF 2015-06. > I've wanted this before as well. But what is the point of %T? Does printing the milliseconds cause some kind of detectable performance hit? I don't think I've ever thought myself "You know, I really wish I hadn't included the milliseconds in that timestamp". Same question for %t, but that ship has already sailed. Cheers, Jeff
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Fabien COELHO writes: >> On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: >>> from time to time I need to correlate PostgreSQL logs to other logs, >>> containing numeric timestamps - a prime example of that is pgbench. With >>> %t and %m that's not quite trivial, because of timezones etc. >> I have a hard time seing this is sufficient cause for adding more format >> codes. They're not free runtime and documentation wise. -0.5 from me. > The proposed format is much simpler to manage in a script, and if you're > interested in runtime, its formatting would be less expensive than %t and > %m. Maybe, but do we really need two? How about just %M? Also, having just one would open the door to calling it something like %u (for Unix timestamp), which would avoid introducing the concept of upper case meaning something-different-from-but-related-to into log_line_prefix format codes. We don't have any upper case codes in there now, and I'd prefer not to go there if we don't have to. regards, tom lane -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: from time to time I need to correlate PostgreSQL logs to other logs, containing numeric timestamps - a prime example of that is pgbench. With %t and %m that's not quite trivial, because of timezones etc. I have a hard time seing this is sufficient cause for adding more format codes. They're not free runtime and documentation wise. -0.5 from me. The proposed format is much simpler to manage in a script, and if you're interested in runtime, its formatting would be less expensive than %t and %m. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 2015-03-22 00:47:12 +0100, Tomas Vondra wrote: > from time to time I need to correlate PostgreSQL logs to other logs, > containing numeric timestamps - a prime example of that is pgbench. With > %t and %m that's not quite trivial, because of timezones etc. I have a hard time seing this is sufficient cause for adding more format codes. They're not free runtime and documentation wise. -0.5 from me. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
I'm not sure that the "." in "%.03d" is useful. ISTM that it is used for floatting point formatting, but is not needed with integers. It is needed for integers, because you need to make sure 1 millisecond is formatted as .001 and not .1. ISTM that the "03" does that on its own: sh> printf "%03d\n" 0 1 2 000 001 002 -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22.3.2015 08:14, David Rowley wrote: > Hi Tomas, > > I just had a quick glance at this. > Is there a reason you didn't include code to support the space padding > for the new log_line_prefixes? > The others support % in the prefix, to allow left or > right alignment of the item. Didn't realize that, will fix in the next version. > > Also, what's the reason for timestamp_str? Could you not just use > appendStringInfo() and skip the temporary buffer? Yeah, that's probably a good idea too. > > Regards > > David Rowley -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22.3.2015 16:58, Fabien COELHO wrote: > > About the feature: I find it is a good thing. It may help scripting over > the logs, for instance to compute delays between events, whereas the > full date-time-tz syntax is maybe nice but heavier to work with afterwards. > > In addition to the comments already made (typo in doc, padding...): > > +sprintf(timestamp_str, "%ld.%.03d", > +tv.tv_sec, (int)(tv.tv_usec / 1000)); > > I'm not sure that the "." in "%.03d" is useful. ISTM that it is used for > floatting point formatting, but is not needed with integers. It is needed for integers, because you need to make sure 1 millisecond is formatted as .001 and not .1. -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
About the feature: I find it is a good thing. It may help scripting over the logs, for instance to compute delays between events, whereas the full date-time-tz syntax is maybe nice but heavier to work with afterwards. In addition to the comments already made (typo in doc, padding...): +sprintf(timestamp_str, "%ld.%.03d", +tv.tv_sec, (int)(tv.tv_usec / 1000)); I'm not sure that the "." in "%.03d" is useful. ISTM that it is used for floatting point formatting, but is not needed with integers. -- Fabien. -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22 March 2015 at 12:47, Tomas Vondra wrote: > > I propose adding two new log_line_prefix escape sequences - %T and %M, > doing the same thing as %t and %m, but formatting the value as a number. > > Hi Tomas, I just had a quick glance at this. Is there a reason you didn't include code to support the space padding for the new log_line_prefixes? The others support % in the prefix, to allow left or right alignment of the item. Also, what's the reason for timestamp_str? Could you not just use appendStringInfo() and skip the temporary buffer? Regards David Rowley
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
Bruce Momjian wrote: > On Sun, Mar 22, 2015 at 02:41:44AM +0100, Tomas Vondra wrote: > > > Uh, I think you mean "number" here: > > > > > > Time stamp without milliseconds (as a numer) > > > - > > > > Oh, right, that's a stupid typo. > > > > > > > > Also, what "number" do you mean? Unix time since 1970? > > > > Yes, the usual unix timestamp. > > I think you need to find out where we reference that and use the same > wording. We use "Unix epoch" in various places. -- Álvaro Herrerahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Sun, Mar 22, 2015 at 02:41:44AM +0100, Tomas Vondra wrote: > > Uh, I think you mean "number" here: > > > > Time stamp without milliseconds (as a numer) > > - > > Oh, right, that's a stupid typo. > > > > > Also, what "number" do you mean? Unix time since 1970? > > Yes, the usual unix timestamp. I think you need to find out where we reference that and use the same wording. -- Bruce Momjian http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. + -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On 22.3.2015 02:35, Bruce Momjian wrote: > On Sun, Mar 22, 2015 at 12:47:12AM +0100, Tomas Vondra wrote: >> Hi, >> >> from time to time I need to correlate PostgreSQL logs to other logs, >> containing numeric timestamps - a prime example of that is pgbench. With >> %t and %m that's not quite trivial, because of timezones etc. >> >> I propose adding two new log_line_prefix escape sequences - %T and %M, >> doing the same thing as %t and %m, but formatting the value as a number. >> >> Patch attached, I'll add it to CF 2015-06. > > Uh, I think you mean "number" here: > > Time stamp without milliseconds (as a numer) > - Oh, right, that's a stupid typo. > > Also, what "number" do you mean? Unix time since 1970? Yes, the usual unix timestamp. -- Tomas Vondrahttp://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] PATCH: numeric timestamp in log_line_prefix
On Sun, Mar 22, 2015 at 12:47:12AM +0100, Tomas Vondra wrote: > Hi, > > from time to time I need to correlate PostgreSQL logs to other logs, > containing numeric timestamps - a prime example of that is pgbench. With > %t and %m that's not quite trivial, because of timezones etc. > > I propose adding two new log_line_prefix escape sequences - %T and %M, > doing the same thing as %t and %m, but formatting the value as a number. > > Patch attached, I'll add it to CF 2015-06. Uh, I think you mean "number" here: Time stamp without milliseconds (as a numer) - Also, what "number" do you mean? Unix time since 1970? -- Bruce Momjian http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. + -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers