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(, 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(_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(_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(_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(, 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(_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();
+ saved_timeval_set = false;
formatted_log_time[0] = '\0';
log_line_prefix(, 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: > 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 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
> 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
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
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(, 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
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
entryno/entry
/row
row
+ entryliteral%n/literal/entry
+ entryTime stamp with milliseconds (as a Unix epoch)/entry
+ entryno/entry
+/row
+row
entryliteral%i/literal/entry
entryCommand tag: type of session's current command/entry
entryyes/entry
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/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
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
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
entryno/entry
/row
row
+ entryliteral%n/literal/entry
+ entryTime stamp with milliseconds (as a Unix epoch)/entry
+ entryno/entry
+/row
+row
entryliteral%i/literal/entry
entryCommand tag: type of session's current command/entry
entryyes/entry
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
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
entryno/entry
/row
row
+ entryliteral%n/literal/entry
+ entryTime stamp with milliseconds (as a Unix epoch)/entry
+ entryno/entry
+/row
+row
entryliteral%i/literal/entry
entryCommand tag: type of session's current command/entry
entryyes/entry
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
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
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 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
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 22 March 2015 at 12:47, Tomas Vondra tomas.von...@2ndquadrant.com 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 %paddingchar 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
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
Fabien COELHO coe...@cri.ensmp.fr 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 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 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
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 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
On Sat, Mar 21, 2015 at 4:47 PM, Tomas Vondra tomas.von...@2ndquadrant.com 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
[HACKERS] PATCH: numeric timestamp in log_line_prefix
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.
regards
--
Tomas Vondrahttp://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 b30c68d..7f39b18 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -4636,11 +4636,21 @@ local0.*/var/log/postgresql
entryno/entry
/row
row
+ entryliteral%T/literal/entry
+ entryTime stamp without milliseconds (as a numer)/entry
+ entryno/entry
+/row
+row
entryliteral%m/literal/entry
entryTime stamp with milliseconds/entry
entryno/entry
/row
row
+ entryliteral%M/literal/entry
+ entryTime stamp with milliseconds (as a number)/entry
+ entryno/entry
+/row
+row
entryliteral%i/literal/entry
entryCommand tag: type of session's current command/entry
entryyes/entry
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index b952c7c..abafdd9 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -2428,6 +2428,19 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
else
appendStringInfoString(buf, formatted_log_time);
break;
+ case 'M':
+{
+ struct timeval tv;
+ char timestamp_str[FORMATTED_TS_LEN];
+
+ gettimeofday(tv, NULL);
+
+ sprintf(timestamp_str, %ld.%.03d,
+ tv.tv_sec, (int)(tv.tv_usec / 1000));
+
+ appendStringInfoString(buf, timestamp_str);
+}
+break;
case 't':
{
pg_time_t stamp_time = (pg_time_t) time(NULL);
@@ -2442,6 +2455,18 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
appendStringInfoString(buf, strfbuf);
}
break;
+ case 'T':
+{
+ struct timeval tv;
+ char timestamp_str[FORMATTED_TS_LEN];
+
+ gettimeofday(tv, NULL);
+
+ sprintf(timestamp_str, %ld, tv.tv_sec);
+
+ appendStringInfoString(buf, timestamp_str);
+}
+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 110983f..e448dd0 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -425,7 +425,9 @@
# %h = remote host
# %p = process ID
# %t = timestamp without milliseconds
+ # %T = timestamp without milliseconds (as a number)
# %m = timestamp with milliseconds
+ # %M = timestamp with milliseconds (as a number)
# %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 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: entryTime stamp without milliseconds (as a numer)/entry - 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 02:41:44AM +0100, Tomas Vondra wrote: Uh, I think you mean number here: entryTime stamp without milliseconds (as a numer)/entry - 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 br...@momjian.ushttp://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
Bruce Momjian wrote: On Sun, Mar 22, 2015 at 02:41:44AM +0100, Tomas Vondra wrote: Uh, I think you mean number here: entryTime stamp without milliseconds (as a numer)/entry - 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 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: entryTime stamp without milliseconds (as a numer)/entry - Also, what number do you mean? Unix time since 1970? -- Bruce Momjian br...@momjian.ushttp://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
