Subject: Re: High Resolution Timing
From: (Rob Warnock)
Date: Tue, 02 Aug 2005 02:23:54 -0500
Newsgroups: comp.lang.lisp
Message-ID: <>
Alex <> wrote:
| ...want to make sure that the time  between two calls is recorded pretty
| exactly, and that it somehow corresponds to the wall time.
| get-universal-time and the related functions are only precise to the
| second.  I was thinking that one options was to call get-universal-time
| at the startup of the program and use it as a baseline; then, I could
| use get-internal-real-time to get precise timing since startup and
| combine the two.

Note that ANSI CL only defines GET-INTERNAL-REAL-TIME in terms of
the difference of two calls to itself, *not* in terms of the time
"since startup" per se. This may seem like a subtle point, but I
got burned on it once and so am mentioning it here.

For example, in CMUCL (and quite possibly SBCL), the virtual timer
associated with GET-INTERNAL-REAL-TIME only starts at the first call
[actually, slightly *before*!], *not* when the Lisp image itself starts
running. If one is not aware of this, the results may prove unexpected: ;-}

    > internal-time-units-per-second

    > (list (get-universal-time)
	    (sleep 10)
	    (sleep 10)

    (3331954170 NIL 3331954180 82 NIL 3331954190 1082)

Although the first call to GET-INTERNAL-REAL-TIME was over 10 seconds
after startup, the first value returned was only 0.82 seconds. The
value of the second call is indeed 10.0 seconds after the first, i.e.,
(/ (- 1082 82) 100).

save them as a baseline, but then use only differences between
the saved GET-INTERNAL-REAL-TIME and the current value for your
fine timing.

Though if needed for human consumption, e.g., for log messages with
fractions of a second, with only a little effort you can add such
differences back to the saved baseline GET-UNIVERSAL-TIME, e.g. some
code I wrote for an HTTP app server [FORMAT-TIME-CTIME is my own hack,
but you can probably tweak CMUCL/SBCL's FORMAT-UNIVERSAL-TIME into
something usable]:

    (defvar *initial-universal-time* (get-universal-time))
    (defvar *initial-real-time* (get-internal-real-time))
    (defvar *log-stream* *standard-output*)	; Might be rebound

    (defun log-time ()
      (multiple-value-bind (delta-secs delta-ticks)
	  (floor (/ (- (get-internal-real-time) *initial-real-time*)
      (let ((now-secs (+ *initial-universal-time* delta-secs)))
	(format nil "~a~3,2f" (subseq (format-time-ctime now-secs) 4 19)

    (defun log-msg (format &rest format-args)
      (format *log-stream* "~&; ~A ~?~%" (log-time) format format-args)
      (force-output *log-stream*))

This produces messages such as the following:

    > (log-msg "Hello, world!")
    ; Aug  1 23:59:01.04 Hello, world!
    > (log-msg "Keep on truckin,~{ ~a~}..." '(1 2 3))
    ; Aug  1 23:59:19.88 Keep on truckin, 1 2 3...


p.s. Even with this approach, the entire sequence of reported log times
may be off from "wall clock" time by as much as a second, due to the
granularity of the results of the first call to GET-UNIVERSAL-TIME.
Differences between two log messages should be correct, though, within

Rob Warnock			<>
627 26th Avenue			<URL:>
San Mateo, CA 94403		(650)572-2607