Re: microsecond log timestamps

Someone probably had a good reason for doing this, but looking at
backend/utils/error/elog.c line 592 in 7.1, it looks like the pre-7.1
capability for microsecond timestamp granularity (e.g.,
20010511.14:23:49.325) in tprintf_timestamp() was removed in favor of a
coarser 1-second resolution using time_t in print_timestamp()? Is that
correct? If not, what am I missing?

If so, is anyone aware of an existing patch to give sub-second log
timestamp capability? Microsecond granularity has been very helpful for
query timing.

Regards,
Ed Loehr

> If so, is anyone aware of an existing patch to give sub-second log
> timestamp capability?

I guess one could just substitute the old tprintf_timestamp() from
pre-7.1. code...

Regards,
Ed Loehr

Ed Loehr <eloehr(at)austin(dot)rr(dot)com> writes:
> Someone probably had a good reason for doing this, but looking at
> backend/utils/error/elog.c line 592 in 7.1, it looks like the pre-7.1
> capability for microsecond timestamp granularity (e.g.,
> 20010511.14:23:49.325) in tprintf_timestamp() was removed in favor of a
> coarser 1-second resolution using time_t in print_timestamp()? Is that
> correct? If not, what am I missing?

> If so, is anyone aware of an existing patch to give sub-second log
> timestamp capability? Microsecond granularity has been very helpful for
> query timing.

I can't see any good reason that print_timestamp() shouldn't use
gettimeofday() rather than time(); certainly there's no portability
argument for it, because we use gettimeofday in several other places.

Feel free to submit a patch...

regards, tom lane

Tom Lane wrote:
>
> Ed Loehr <eloehr(at)austin(dot)rr(dot)com> writes:
> > Someone probably had a good reason for doing this, but looking at
> > backend/utils/error/elog.c line 592 in 7.1, it looks like the pre-7.1
> > capability for microsecond timestamp granularity (e.g.,
> > 20010511.14:23:49.325) in tprintf_timestamp() was removed in favor of a
> > coarser 1-second resolution using time_t in print_timestamp()? Is that
> > correct? If not, what am I missing?
>
> > If so, is anyone aware of an existing patch to give sub-second log
> > timestamp capability? Microsecond granularity has been very helpful for
> > query timing.
>
> I can't see any good reason that print_timestamp() shouldn't use
> gettimeofday() rather than time(); certainly there's no portability
> argument for it, because we use gettimeofday in several other places.
>
> Feel free to submit a patch...

The attached patch restores pre-7.1 millisecond-granularity log
timestamps (except that it also adds a 4-digit year, which was not in
pre-7.1). It is meant to be applied to
postgresql-7.1/src/backend/utils/error/elog.c.

Regards,
Ed Loehr

Ed Loehr writes:

> The attached patch restores pre-7.1 millisecond-granularity log
> timestamps (except that it also adds a 4-digit year, which was not in
> pre-7.1). It is meant to be applied to
> postgresql-7.1/src/backend/utils/error/elog.c.

I am opposed to the unreadable, non-standard timestamp format. I also
don't see the point of microsecond granularity. There are much better
ways to time a query. (Or at least we could provide some.)

--
Peter Eisentraut peter_e(at)gmx(dot)net http://funkturm.homeip.net/~peter

On Sun, 13 May 2001, Peter Eisentraut wrote:

> Ed Loehr writes:
>
> > The attached patch restores pre-7.1 millisecond-granularity log
> > timestamps (except that it also adds a 4-digit year, which was not in
> > pre-7.1). It is meant to be applied to
> > postgresql-7.1/src/backend/utils/error/elog.c.
>
> I am opposed to the unreadable, non-standard timestamp format. I also
> don't see the point of microsecond granularity. There are much better
> ways to time a query. (Or at least we could provide some.)

How about using the TAI format? http://cr.yp.to/libtai/tai64.html

Vince.
--
==========================================================================
Vince Vielhaber -- KA8CSH email: vev(at)michvhf(dot)com http://www.pop4.net
56K Nationwide Dialup from $16.00/mo at Pop4 Networking
Online Campground Directory http://www.camping-usa.com
Online Giftshop Superstore http://www.cloudninegifts.com
==========================================================================

Peter Eisentraut <peter_e(at)gmx(dot)net> writes:
> I am opposed to the unreadable, non-standard timestamp format.

I didn't see the point of Ed's arbitrary change in YMD format, but
what's wrong with adding fractional seconds? Our own timestamp code
is willing to format fractional seconds, so we can hardly call it
nonstandard.

> I also don't see the point of microsecond granularity.

What Ed implemented (which is what was in 7.0 and before) is millisecond
resolution, which does seem worthwhile; certainly one-second resolution
is pretty coarse on some machines these days.

I was thinking of keeping the YMD display format the same but otherwise
adopting the patch.

regards, tom lane

Tom Lane wrote:
>
> Peter Eisentraut <peter_e(at)gmx(dot)net> writes:
> > I am opposed to the unreadable, non-standard timestamp format.
>
> I didn't see the point of Ed's arbitrary change in YMD format, but
> what's wrong with adding fractional seconds? Our own timestamp code
> is willing to format fractional seconds, so we can hardly call it
> nonstandard.

Out of respect to existing log-processing programs, I tried to adhere to
the pgsql traditional (pre-7.1) format, except that I'd added a 4-digit
year I'd been patching since 6.5.2, which probably ended up breaking them
anyway.

> > I also don't see the point of microsecond granularity.
>
> What Ed implemented (which is what was in 7.0 and before) is millisecond
> resolution, which does seem worthwhile; certainly one-second resolution
> is pretty coarse on some machines these days.

Yes, microsecond was a typo. I meant milliseconds.

> I was thinking of keeping the YMD display format the same but otherwise
> adopting the patch.

That'd be an improvement. Unfortunately, the ISO 8601 standard is not
much more readable:

2001-05-13T10:19:44,085-05:00

That's a literal 'T' designating the time portion and a comma separating
seconds and milliseconds (http://www.iso.ch/markete/8601.pdf)

Regards,
Ed Loehr

> That'd be an improvement. Unfortunately, the ISO 8601 standard is not
> much more readable:
> 2001-05-13T10:19:44,085-05:00
> That's a literal 'T' designating the time portion and a comma separating
> seconds and milliseconds (http://www.iso.ch/markete/8601.pdf)

No disagreement here, but f-y'all-i the standard says that the 'T' is
allowed to be omitted if acceptable to both parties handling the data.

- Thomas