Thread: 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
Ed Loehr <eloehr@austin.rr.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@austin.rr.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*** /usr/src/postgresql-7.1/src/backend/utils/error/elog.c.dist Fri May 11 17:42:28 2001
--- /usr/src/postgresql-7.1/src/backend/utils/error/elog.c Sun May 13 00:45:53 2001
***************
*** 65,71 ****
bool Log_timestamp;
bool Log_pid;
! #define TIMESTAMP_SIZE 20 /* format `YYYY-MM-DD HH:MM:SS ' */
#define PID_SIZE 9 /* format `[123456] ' */
static const char *print_timestamp(void);
--- 65,71 ----
bool Log_timestamp;
bool Log_pid;
! #define TIMESTAMP_SIZE 22 /* format `YYYYMMDD.HH:MM:SS.sss ' */
#define PID_SIZE 9 /* format `[123456] ' */
static const char *print_timestamp(void);
***************
*** 575,599 ****
/*
! * Return a timestamp string like
! *
! * "2000-06-04 13:12:03 "
*/
static const char *
print_timestamp(void)
{
! time_t curtime;
! static char buf[TIMESTAMP_SIZE + 1];
!
! curtime = time(NULL);
! strftime(buf, sizeof(buf),
! "%Y-%m-%d %H:%M:%S ",
! localtime(&curtime));
!
! return buf;
}
-
/*
--- 575,602 ----
/*
! * Return a timestamp string like "20010119.17:25:59.902 "
*/
static const char *
print_timestamp(void)
{
! struct timeval tv;
! struct timezone tz = {0, 0};
! struct tm *time;
! time_t tm;
! static char timestamp[TIMESTAMP_SIZE + 1];
!
! gettimeofday(&tv, &tz);
! tm = tv.tv_sec;
! time = localtime(&tm);
!
! sprintf(timestamp, "%4d%02d%02d.%02d:%02d:%02d.%03d ",
! time->tm_year + 1900, time->tm_mon + 1, time->tm_mday,
! time->tm_hour, time->tm_min, time->tm_sec,
! (int) (tv.tv_usec / 1000));
! return timestamp;
}
/*
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@gmx.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@michvhf.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@gmx.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@gmx.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