[Openmcl-devel] Profiling lisp code

[Taoufik Dachraoui]

Hi,

I created a macro with-profiler and would like to know the  
disadvantages of this solution
compared to others:

; i took the following 2 functions from ccl-1.4/tools/advice-profiler/ 
profiler.lisp
; the with-profiler can be modified to return cpu-time, user-time and  
real-time used
; by all profiled functions

(defun mach-timespec->nanoseconds (ts)
   "Convert the given typespec structure into nanoseconds."
   (+ (* 1000000000 (pref ts :mach_timespec.tv_sec))
      (pref ts :mach_timespec.tv_nsec)))

(defun get-real-time ()
   (let ((clock-port (make-record :clock_serv_t)))
     (#_host_get_clock_service (#_mach_host_self) #$REALTIME_CLOCK  
clock-port)
     (ccl:rlet ((ts :mach_timespec))
	      (#_clock_get_time (%get-ptr clock-port) ts)
	      (mach-timespec->nanoseconds ts))))

(defmacro with-profiler (syms &rest body)
   `(let ((*profiler* (make-hash-table :test #'equal)))
     (dolist (s ',syms)
       (setf (gethash `,s *profiler*) '(nil 0 0))
       (CCL::%UNTRACE-0 `(,s))
       (CCL::%TRACE-0 `((,s :before #'(lambda (f &rest vals)
				       (declare (ignore vals))
				       (multiple-value-bind (last count elapsed) (values-list  
(gethash f *profiler*))
					 (declare (ignore last))
					 (setf (gethash f *profiler*) (list (get-real-time) (+ 1 count)  
elapsed))))
			   :after #'(lambda (f &rest vals)
				       (declare (ignore vals))
				       (multiple-value-bind (last count elapsed) (values-list  
(gethash f *profiler*))
					 (let ((tim (get-real-time)))
					   (setf (gethash f *profiler*) (list tim count (+ elapsed (- tim  
last)))))))))
		     'NIL))
     (format t "~%profiling ~A~%" (trace))
     (let ((elapsed (get-real-time)))
       (eval '(progn , at body))
       (format t "total elapsed time ~S~%" (- (get-real-time) elapsed)))
     (dolist (s ',syms)
       (CCL::%UNTRACE-0 `(,s)))
     (maphash #'(lambda (k v) (format t "function=~S count=~S  
elapsed=~S~%" k (second v) (third v))) *profiler*)))

Tests:

? (defun fact (n) (if (= 0 n) 1 (* n (fact (- n 1)))))
? (defun f () (sleep 1))
? (defmacro foo () (progn (f) ''foo))
? (with-profiler (f fact)
	(dotimes (i 10)
	    (f)
	    (foo)
	    (fact (random 100))))

profiling (FACT F)
total elapsed time 11003452329
function=FACT count=10 elapsed=268738
function=F count=11 elapsed=11001194423
NIL
?

Any comments on this method of profiling lisp functions are welcome

Kind regards
Taoufik

On Nov 18, 2009, at 5:57 PM, Matt Tenenbaum wrote:

>
> Norvig's classic "Paradigms of Artificial Intelligence Programming"
> has a section on instrumentation in chapter 9, including code for
> profiling in a manner analogous to TRACE. In looking quickly, this
> code doesn't seem to be included in the distributed source for the
> book (http://norvig.com/paip/README.html), but you might find that
> chapter helpful.
>
> Cheers,
> -mt
>
> On Wed, Nov 18, 2009 at 8:36 AM, Taoufik Dachraoui
> <taoufik.dachraoui at wanadoo.fr> wrote:
>> Hi
>>
>> How do I profile lisp program to know how much time each called
>> function takes
>>
>> Regards
>> Taoufik
>>
>>
>>
>> _______________________________________________
>> Openmcl-devel mailing list
>> Openmcl-devel at clozure.com
>> http://clozure.com/mailman/listinfo/openmcl-devel
>>
>