Thread: Finer grain log timestamps

Folks,

Please find attached a patch to change the sub-second granularity of
log timestamps from milliseconds to  microseconds.

I started out working on a longer patch that will give people
more choices than whole seconds and microseconds, but there were a lot
of odd corner cases, including what I believe might have been a
requirement for C11, should be wish to get sub-microsecond
granularity.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

On Sun, May 08, 2022 at 08:44:51PM +0000, David Fetter wrote:
>  CREATE TABLE postgres_log
>  (
> -  log_time timestamp(3) with time zone,
> +  log_time timestamp(6) with time zone,

Please also update the corresponding thing in doc/src/sgml/file-fdw.sgml

It looks like the patch I suggested to include a reminder about this was never
applied.
https://www.postgresql.org/message-id/10995044.nUPlyArG6x@aivenronan

See also:
e568ed0eb07239b7e53d948565ebaeb6f379630f
0830d21f5b01064837dc8bd910ab31a5b7a1101a

On Sun, May 08, 2022 at 04:12:27PM -0500, Justin Pryzby wrote:
> On Sun, May 08, 2022 at 08:44:51PM +0000, David Fetter wrote:
> >  CREATE TABLE postgres_log
> >  (
> > -  log_time timestamp(3) with time zone,
> > +  log_time timestamp(6) with time zone,
> 
> Please also update the corresponding thing in doc/src/sgml/file-fdw.sgml

Thanks for looking this over, and please find attached the next
version.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

David Fetter <david@fetter.org> writes:

> diff --git src/backend/utils/error/elog.c src/backend/utils/error/elog.c
> index 55ee5423af..4698e32ab7 100644
> --- src/backend/utils/error/elog.c
> +++ src/backend/utils/error/elog.c
> @@ -2295,7 +2295,7 @@ char *
>  get_formatted_log_time(void)
>  {
>      pg_time_t    stamp_time;
> -    char        msbuf[13];
> +    char        msbuf[16];

Now that it holds microseconds (µs), not milliseconds (ms), should it
not be renamed to `usbuf`?

- ilmari

On Mon, May 09, 2022 at 11:21:26AM +0100, Dagfinn Ilmari Mannsåker wrote:
> David Fetter <david@fetter.org> writes:
> 
> > diff --git src/backend/utils/error/elog.c src/backend/utils/error/elog.c
> > index 55ee5423af..4698e32ab7 100644
> > --- src/backend/utils/error/elog.c
> > +++ src/backend/utils/error/elog.c
> > @@ -2295,7 +2295,7 @@ char *
> >  get_formatted_log_time(void)
> >  {
> >      pg_time_t    stamp_time;
> > -    char        msbuf[13];
> > +    char        msbuf[16];
> 
> Now that it holds microseconds (µs), not milliseconds (ms), should it
> not be renamed to `usbuf`?

Good point.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

On Sun, May 8, 2022 at 4:45 PM David Fetter <david@fetter.org> wrote:
> Please find attached a patch to change the sub-second granularity of
> log timestamps from milliseconds to  microseconds.

Why is this a good idea?

-- 
Robert Haas
EDB: http://www.enterprisedb.com

Robert Haas <robertmhaas@gmail.com> writes:
> On Sun, May 8, 2022 at 4:45 PM David Fetter <david@fetter.org> wrote:
>> Please find attached a patch to change the sub-second granularity of
>> log timestamps from milliseconds to  microseconds.

> Why is this a good idea?

I can imagine that some people would have a use for microsecond
resolution in log files, and I can also imagine that as machines
get faster more people will want that.  As against that, this
will bloat log files by a non-microscopic amount, and it's pretty
likely to break some log-scanning tools too.  It's unclear to me
that that's a tradeoff we should force on everyone.

I think a proposal less likely to have push-back would be to invent
a different log_line_prefix %-escape to produce microseconds.
Sadly, "%u" is already taken, but perhaps we could use "%U"?

A different line of thought is to extend %t to provide a precision
field a la sprintf, so that for example "%.3t" is equivalent to
"%m" and "%.6t" does what David wants, and we won't have to
search for a new escape letter when the day arrives that
somebody wants nanosecond resolution.  The same could be done
with %n, avoiding the need to find a different escape letter
for that.

            regards, tom lane

On Mon, Jun 13, 2022 at 04:22:42PM -0400, Tom Lane wrote:
> Robert Haas <robertmhaas@gmail.com> writes:
> > On Sun, May 8, 2022 at 4:45 PM David Fetter <david@fetter.org> wrote:
> >> Please find attached a patch to change the sub-second granularity of
> >> log timestamps from milliseconds to  microseconds.
> 
> > Why is this a good idea?
> 
> I can imagine that some people would have a use for microsecond
> resolution in log files, and I can also imagine that as machines
> get faster more people will want that.

Your imagination matches situations I've seen in production where
there was some ambiguity as to what happened when inside a millisecond
boundary, and I'm sure I'm not alone in this.  I've gotten this
request from at least three people who to my knowledge knew nothing
about each other, and as I recall, the first time someone brought it
up to me was over five years back.

> As against that, this will bloat log files by a non-microscopic
> amount, and it's pretty likely to break some log-scanning tools too.

Three bytes per line, and log-scanning parsers that finicky are
already breaking all the time, respectively.

> It's unclear to me that that's a tradeoff we should force on
> everyone.

The tradeoff we're forcing on people at the moment is a loss of
precision they didn't ask for, implemented by some extra instructions
they didn't ask us to execute in a part of the code that's a hot path
at exactly the times when the machine is busiest.

> I think a proposal less likely to have push-back would be to invent
> a different log_line_prefix %-escape to produce microseconds.
> Sadly, "%u" is already taken, but perhaps we could use "%U"?
> 
> A different line of thought is to extend %t to provide a precision
> field a la sprintf, so that for example "%.3t" is equivalent to
> "%m" and "%.6t" does what David wants, and we won't have to
> search for a new escape letter when the day arrives that
> somebody wants nanosecond resolution.  The same could be done
> with %n, avoiding the need to find a different escape letter
> for that.

I'll build this more sprintf-like thing if not doing so prevents the
change from happening, but frankly, I don't really see a point in it
because the next "log timestamps at some random negative power of 10
second granularity" requirement I see will be the first.

Best,
David.
-- 
David Fetter <david(at)fetter(dot)org> http://fetter.org/
Phone: +1 415 235 3778

Remember to vote!
Consider donating to Postgres: http://www.postgresql.org/about/donate

On 2022-Jun-14, David Fetter wrote:

> On Mon, Jun 13, 2022 at 04:22:42PM -0400, Tom Lane wrote:

> > A different line of thought is to extend %t to provide a precision
> > field a la sprintf, so that for example "%.3t" is equivalent to
> > "%m" and "%.6t" does what David wants, and we won't have to
> > search for a new escape letter when the day arrives that
> > somebody wants nanosecond resolution.  The same could be done
> > with %n, avoiding the need to find a different escape letter
> > for that.
> 
> I'll build this more sprintf-like thing if not doing so prevents the
> change from happening, but frankly, I don't really see a point in it
> because the next "log timestamps at some random negative power of 10
> second granularity" requirement I see will be the first.

Do we *have* to provide support for arbitrary numbers of digits, though?
We could provide support for only %.3t and %.6t specifically, and not
worry about other cases (error: width not supported).  When somebody
wants %.9t in ten years, we won't have to fight for which letter to
pick.  And I agree that widening %m for everybody without recourse is
not great.

-- 
Álvaro Herrera        Breisgau, Deutschland  —  https://www.EnterpriseDB.com/

Alvaro Herrera <alvherre@alvh.no-ip.org> writes:
> Do we *have* to provide support for arbitrary numbers of digits, though?
> We could provide support for only %.3t and %.6t specifically, and not
> worry about other cases (error: width not supported).

If I were coding it, I would allow only exactly 1 digit (%.Nt) to simplify
the parsing side of things and bound the required buffer size.  Without
having written it, it's not clear to me whether further restricting the
set of supported values would save much code.  I will point out, though,
that throwing an error during log_line_prefix processing will lead
straight to infinite recursion.

            regards, tom lane

This entry has been waiting on author input for a while (our current
threshold is roughly two weeks), so I've marked it Returned with
Feedback.

Once you think the patchset is ready for review again, you (or any
interested party) can resurrect the patch entry by visiting

    https://commitfest.postgresql.org/38/3683/

and changing the status to "Needs Review", and then changing the
status again to "Move to next CF". (Don't forget the second step;
hopefully we will have streamlined this in the near future!)

Thanks,
--Jacob