[Openmcl-devel] Profiling lisp code

[Alexander Repenning]

looks great to me. It seems to use similar functions as the timer code I pointed to in my previous post but includes a nice profilers wrap up macro. I suggest to use time formatting functions similar to the code I pointed to because it is not clear what "elapsed=268738" really means. Just a detail.

best,  Alex

On Nov 19, 2009, at 7:24 AM, Taoufik Dachraoui wrote:

> 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
>>> 
>> 
> 
> 
> 
> _______________________________________________
> Openmcl-devel mailing list
> Openmcl-devel at clozure.com
> http://clozure.com/mailman/listinfo/openmcl-devel

Prof. Alexander Repenning

University of Colorado
Computer Science Department
Boulder, CO 80309-430

vCard: http://www.cs.colorado.edu/~ralex/AlexanderRepenning.vcf


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clozure.com/pipermail/openmcl-devel/attachments/20091119/205cdaff/attachment.htm>