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 Vondra http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachments:
log-line-prefix-numeric-timestamp.patchtext/x-diff; name=log-line-prefix-numeric-timestamp.patchDownload
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
<entry>no</entry>
</row>
<row>
+ <entry><literal>%T</literal></entry>
+ <entry>Time stamp without milliseconds (as a numer)</entry>
+ <entry>no</entry>
+ </row>
+ <row>
<entry><literal>%m</literal></entry>
<entry>Time stamp with milliseconds</entry>
<entry>no</entry>
</row>
<row>
+ <entry><literal>%M</literal></entry>
+ <entry>Time stamp with milliseconds (as a number)</entry>
+ <entry>no</entry>
+ </row>
+ <row>
<entry><literal>%i</literal></entry>
<entry>Command tag: type of session's current command</entry>
<entry>yes</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
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:
<entry>Time stamp without milliseconds (as a numer)</entry>
-----
Also, what "number" do you mean? Unix time since 1970?
--
Bruce Momjian <bruce@momjian.us> 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
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:
<entry>Time 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 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
On Sun, Mar 22, 2015 at 02:41:44AM +0100, Tomas Vondra wrote:
Uh, I think you mean "number" here:
<entry>Time 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 <bruce@momjian.us> 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
Bruce Momjian wrote:
On Sun, Mar 22, 2015 at 02:41:44AM +0100, Tomas Vondra wrote:
Uh, I think you mean "number" here:
<entry>Time 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 Herrera 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
On 22 March 2015 at 12:47, Tomas Vondra <tomas.vondra@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 %<padding><char> 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
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
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 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
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 %<padding><char> 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 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
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
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
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
Fabien COELHO <coelho@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
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
On Sat, Mar 21, 2015 at 4:47 PM, Tomas Vondra <tomas.vondra@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
[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
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 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
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 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
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
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 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
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
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
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
Attachments:
log-line-prefix-numeric-timestamp-v2.patchtext/x-diff; name=log-line-prefix-numeric-timestamp-v2.patchDownload
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
<entry>no</entry>
</row>
<row>
+ <entry><literal>%n</literal></entry>
+ <entry>Time stamp with milliseconds (as a Unix epoch)</entry>
+ <entry>no</entry>
+ </row>
+ <row>
<entry><literal>%i</literal></entry>
<entry>Command tag: type of session's current command</entry>
<entry>yes</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
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
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
Attachments:
log-line-prefix-numeric-timestamp-v3.patchtext/x-diff; name=log-line-prefix-numeric-timestamp-v3.patchDownload
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
<entry>no</entry>
</row>
<row>
+ <entry><literal>%n</literal></entry>
+ <entry>Time stamp with milliseconds (as a Unix epoch)</entry>
+ <entry>no</entry>
+ </row>
+ <row>
<entry><literal>%i</literal></entry>
<entry>Command tag: type of session's current command</entry>
<entry>yes</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
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.
Attachments:
log-line-prefix-numeric-timestamp-v4.patchtext/x-diff; name=log-line-prefix-numeric-timestamp-v4.patchDownload
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
<entry>no</entry>
</row>
<row>
+ <entry><literal>%n</literal></entry>
+ <entry>Time stamp with milliseconds (as a Unix epoch)</entry>
+ <entry>no</entry>
+ </row>
+ <row>
<entry><literal>%i</literal></entry>
<entry>Command tag: type of session's current command</entry>
<entry>yes</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
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
+ 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;
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 Herrera 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
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
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 /messages/by-id/20150907192719.GS2912@alvherre.pgsql ?
--
�lvaro Herrera 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
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 /messages/by-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
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]As of minutes ago, after I missed your message by a few minutes.: 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
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 Herrera 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
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
Attachments:
gettimeofday.patchtext/x-patch; charset=UTF-8; name=gettimeofday.patchDownload
*** 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 bool saved_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);
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 Herrera 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