Re: timing

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

On Sun Oct  3, Richard Ferrante writes:
  Is there a simple way to get at the current values of total time spent doing
  GC and time spent in The Cooperative Multitasking Experience?
  Preferably in universal time format so that I can subtract out changes
  find out the actual time spent executing lisp code.
   
  This is for code "introspection" during run time, so using the `time'
  macro isn't appropriate, (portability is not an issue)

Yes, you can access the total amount of time in GC.
No, you can't get access the total time spent in the Cooperative Multitasking
Experience. The time is the difference between the internal-real-time and
the internal-run-time figures.

The following code may help you do what you want.

mark

The functions are briefly described below:

Date-stamp prints a time in readable format. The format is
days: hours::minutes:seconds.

Time-stats returns the values: elapsed time, run time, times for full GC and
ephemeral GC, and counts for full GC and ephemeral GC. The difference 
the time spent outside MCL (aka the Cooperative MultiTasking Experience) is
(- elapsed-time run-time). All of the times are in 
internal-time-units-per-second. Modify date-stamp to return
the time in any units/format that you want.


Format-time-stats prints the run-time,multi-tasking time, and the full gc 
and ephemeral gc times in date-stam format.

;;;; start of code
(defun date-stamp (elapsed)
  (let (hh mm ss dd)
    (setq ss (floor elapsed internal-time-units-per-second)
          mm (floor ss 60)
          ss (mod ss 60)
          hh (floor mm 60)
          mm (mod mm 60)
          dd (floor hh 24)
          hh (mod hh 24))
    (format nil "~3d ~2d:~2d::~2d" dd hh mm ss)))

(defun time-stats ()
  (multiple-value-bind (total-gc-time full-gc-time)
                       (gctime)
    (multiple-value-bind (total-gc-count full-gc-count)
                         (gcCounts)
      (let ((elapsed-time (get-internal-real-time))
            (run-time (get-internal-run-time))
            (ephemeral-gc-time (- total-gc-time full-gc-time))
            (ephemeral-gc-count (- total-gc-count full-gc-count)))
        (values elapsed-time
                run-time
                full-gc-time
                ephemeral-gc-time
                full-gc-count
                ephemeral-gc-count
                )))))

(defun format-time-stats ()
  (multiple-value-bind (elapsed cpu-time full-gc-time ephemeral-gc-time)
                       (time-stats)
    (format t "~&Run time ~20t~a~%Cooperative time ~20t~a~%Gctime full~20t~a~%  
    ephemeral~20t~a~%"
            (date-stamp cpu-time)
            (date-stamp (- elapsed cpu-time))
            (date-stamp full-gc-time)
            (date-stamp ephemeral-gc-time))))
    
? (format-time-stats)
Run time              0  0:15::17
Cooperative time      0  0:40:: 4
Gctime full           0  0: 0:: 3
       ephemeral      0  0: 0:: 0