Alex <bsdfish@gmail.com> 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

    100
    > (list (get-universal-time)
	    (sleep 10)
	    (get-universal-time)
	    (get-internal-real-time)
	    (sleep 10)
	    (get-universal-time)
	    (get-internal-real-time))

    (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).

So call *both* GET-UNIVERSAL-TIME & GET-INTERNAL-REAL-TIME and
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*)
		    internal-time-units-per-second))
      (let ((now-secs (+ *initial-universal-time* delta-secs)))
	(format nil "~a~3,2f" (subseq (format-time-ctime now-secs) 4 19)
			      delta-ticks))))

    (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!
    NIL
    > (log-msg "Keep on truckin,~{ ~a~}..." '(1 2 3))
    ; Aug  1 23:59:19.88 Keep on truckin, 1 2 3...
    NIL
    cmu> 


-Rob

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
(/ INTERNAL-TIME-UNITS-PER-SECOND) seconds.

-----
Rob Warnock			<rpw3@rpw3.org>
627 26th Avenue			<URL:http://rpw3.org/>
San Mateo, CA 94403		(650)572-2607