[Openmcl-devel] Profiling lisp code

[Raffael Cavallaro]

On Nov 19, 2009, at 1:41 PM, Paul Krueger wrote:

> Using this code everything worked fine:

a couple of minor corrections:

1. missing paren after the dolist form that untraces the funcs causes the output to be printed multiple times if multiple functions are traced.
2. possible divide by zero error if total is zero (this was present in Taoufik's original as well).

corrected version below

warmest regards,

Ralph

(defmacro with-profiler (syms &rest body)
  `(let ((*profile-hash* (make-hash-table :test #'equal)))
     (flet ((before-trace (f &rest vals)
              (declare (ignore vals))
              (multiple-value-bind (last count elapsed)
                                   (values-list (gethash f *profile-hash*))
                (declare (ignore last))
                (setf (gethash f *profile-hash*)
                      (list (get-real-time) (+ 1 count) elapsed))))
            (after-trace (f &rest vals)
              (declare (ignore vals))
              (multiple-value-bind (last count elapsed)
                                   (values-list (gethash f *profile-hash*))
                (let ((tim (get-real-time)))
                  (setf (gethash f *profile-hash*)
                        (list tim count (+ elapsed (- tim last))))))))
       (dolist (s ',syms)
         (setf (gethash s *profile-hash*) '(nil 0 0))
         (CCL::%UNTRACE-0 (list s))
         (CCL::%TRACE-0
          (list (list s :before #'before-trace :after #'after-trace))
          'NIL))
       (format t "~%profiling ~A~%" (trace))
       (let ((elapsed (get-real-time)))
         (eval '(progn , at body))
         (format t "total elapsed time ~10,3F seconds~%"
                 (/ (- (get-real-time) elapsed) 1000000000)))
       (dolist (s ',syms)
         (CCL::%UNTRACE-0 (list s)))
       (let ((lst nil) (total 0))
         (maphash #'(lambda (k v) 
                      (incf total (/ (third v) 1000000000))
                      (push (list k (second v) (third v)) lst))
                  *profile-hash*)
         (format t "~35A ~8A ~14A~%" "Function" "Count" "Elapsed")
         (dolist (e (sort lst #'(lambda (e f) (< (third e) (third f)))))
           (format t "~30S ~10d ~10,3F ~5,2F%~%"
                   (first e) (second e)
                   (/ (third e) 1000000000)
                   (* 100 (/ (/ (third e) 1000000000) (max total 1)))))))))

Raffael Cavallaro
raffaelcavallaro at me.com