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

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(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ Everyone has their own god. +

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

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(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ Everyone has their own god. +

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

On 22 March 2015 at 12:47, Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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.

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

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

>> 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.

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

> 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.

Fabien COELHO <coelho(at)cri(dot)ensmp(dot)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

>> 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.

On Sat, Mar 21, 2015 at 4:47 PM, Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)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.

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

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

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

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

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.

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

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

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.

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

>>> 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.

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

> + 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

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

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/[email protected] ?

--
Álvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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/[email protected] ?

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

> 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.

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

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

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