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:

<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