Re: Measuring elapsed CPU time

["Mark A. Tapia" <markt@dgp.toronto.edu>]

On Thu Jan 21 05:07:05 1993, Joung-woo John Kim (joungwoo@mensa.usc.edu)
writes:
   I'm trying to measure teh elasped CPU time during a lisp form has been run.
   ...
   So I tried using builtin function GET-INTERNAL-RUN-TIME as follows,
   but the following function defined by me usually it gives me either 0 or 1 no
   matter how time-consuming task I give it.
John then describes a function of the form:
   (defun CPU-time (form)
   ...
   )
The problem is that the form is evaluated before the body of the
CPU-time function is invoked. If you want to time a function,
you need to convert your function to a macro. The following
macro does what you want


	    
;; monitoring routines for timing
;; execute the form ntimes and give the title to it
(defpackage :timing (:use "COMMON-LISP" "CCL"))
(in-package :timing)

;; Execute form ntimes, optionally garbage collect (:gc t),
;; optionally prints the statistics (:print t), and
;; returns the following values and optionally prints them
;;     title
;;     number of times the form was executed
;;     total cpu time
;;     cpu time less gc time
;;     total gc time
;;     ephemeral gc time
(defmacro form-stats (title form  &key (ntimes 1) (print t) (gc nil))
  (let ((var1 (gensym))
        (tot (gensym))
        (run (gensym))
        (values (gensym))
        (tot-gc (gensym))
        (new-gc (gensym))
        (egc (gensym))
        (new-egc (gensym)))
    `(let (,tot ,run ,values)
       (when ,gc
         (gc))
       (ccl::reset-consing)
       (multiple-value-bind (,tot-gc ,egc) 
                            (gctime)
         (setq ,egc (- ,tot-gc ,egc))
         (setq ,run (get-internal-run-time))
         (dotimes (,var1 ,ntimes)
           ,form)
         (multiple-value-bind (,new-gc ,new-egc)
                              (gctime)
           (setq ,new-egc (- ,new-gc ,new-egc))
           (setq ,tot-gc (- ,new-gc ,tot-gc)
                 ,egc (- ,new-egc  ,egc)
                 ,tot (- (get-internal-run-time) , run)
                 ,run (- ,tot ,tot-gc) 
                 ,run (float (/ ,run internal-time-units-per-second))
                 ,tot-gc (float (/ ,tot-gc internal-time-units-per-second))
                 ,egc (float (/ ,egc internal-time-units-per-second))
                 ,tot (float (/ ,tot ,internal-time-units-per-second)))
           (setq ,values
                 (format nil "~s ~d ~3f ~3f ~3f ~3f",title ,ntimes ,tot ,run  
                         ,tot-gc ,egc))
           (when ,print (format t "~&~a~%" ,values))
           (values ,title ,ntimes ,tot ,run ,tot-gc ,egc)
           )))))
  
? (form-stats "simple loop"
                (loop for i fixnum from 1 to 10000
                      collect i))
"simple loop" 1 1.1 0.13 1.0 1.0
"simple loop"
1
1.15
0.133
1.017
1.017


mark

You can also collect statistics on storage used.