Hello,
I'm interested in getting pretty precise timestamps, somewith with
sub-second resolution. I am not terribly interested in having the time
be the "exact" time in relation to any absolute standard; rather, I
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. Any cleaner ideas?
Thanks,
Alex Simma
PS I'm using SBCL, but if possible, portable solutions are preferred.
Alex <·······@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.org>
627 26th Avenue <URL:http://rpw3.org/>
San Mateo, CA 94403 (650)572-2607
····@rpw3.org (Rob Warnock) writes:
> (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.
Of course. You must spend one second to synchronize clocks:
(defvar *initial-universal-time* (1+ (get-universal-time)))
(defvar *initial-real-time*
(loop initially (get-internal-real-time)
while (< (get-universal-time) *initial-universal-time*)
finally (return (get-internal-real-time))))
--
__Pascal Bourguignon__ http://www.informatimago.com/
Pascal Bourguignon <····@mouse-potato.com> wrote:
+---------------
| ····@rpw3.org (Rob Warnock) writes:
| > 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.
|
| Of course. You must spend one second to synchronize clocks:
|
| (defvar *initial-universal-time* (1+ (get-universal-time)))
| (defvar *initial-real-time*
| (loop initially (get-internal-real-time)
| while (< (get-universal-time) *initial-universal-time*)
| finally (return (get-internal-real-time))))
+---------------
Heh. Cute. Well, ugly & cute at the same time... ;-} ;-}
-Rob
-----
Rob Warnock <····@rpw3.org>
627 26th Avenue <URL:http://rpw3.org/>
San Mateo, CA 94403 (650)572-2607