Thread: microsecond log timestamps

microsecond log timestamps

From
Ed Loehr
Date:
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

Re: microsecond log timestamps

From
Tom Lane
Date:
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

Re: microsecond log timestamps

From
Ed Loehr
Date:
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;
  }


  /*

Re: [PATCHES] Re: microsecond log timestamps

From
Peter Eisentraut
Date:
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


Re: [PATCHES] Re: microsecond log timestamps

From
Vince Vielhaber
Date:
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
==========================================================================




Re: [PATCHES] Re: microsecond log timestamps

From
Tom Lane
Date:
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

Re: [PATCHES] Re: microsecond log timestamps

From
Ed Loehr
Date:
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

Re: [PATCHES] Re: microsecond log timestamps

From
Thomas Lockhart
Date:
> 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