[Openmcl-devel] Profiling lisp code
Paul Krueger
plkrueger at comcast.net
Thu Nov 19 10:41:11 PST 2009
Taoufik,
I really like this idea, but unfortunately the code as written didn't
work for me.
I first created a couple of test functions:
(defun test-factorial (n)
(if (<= n 1)
1
(* n (test-factorial (1- n)))))
(defun test-profile ()
(with-profiler (test-factorial)
(dotimes (i 1000)
(test-factorial (random 50)))))
but on executing the test-profile function the macro-expansion caused
the following:
(test-profile)
;Compiler warnings :
; In an anonymous lambda form inside (CCL::TRACED TEST-FACTORIAL):
Undeclared free variable *PROFILER* (2 references)
; In an anonymous lambda form inside (CCL::TRACED TEST-FACTORIAL):
Undeclared free variable *PROFILER* (2 references)
profiling (TEST-FACTORIAL)
> Error: Unbound variable: *PROFILER*
> While executing: (:INTERNAL (CCL::TRACED TEST-FACTORIAL)), in
process Listener(6).
> Type cmd-. to abort, cmd-\ for a list of available restarts.
> Type :? for other options.
1 >
This is caused by the use of the ` form for the trace-0 argument
calls which effectively hides the let declaration of *profiler*
because you are passing a list that contains the unevaluated lambda
form to trace rather than passing a list that contains the function
that results from evaluation of that form within the scope of the let.
Even if we fixed just that problem, this code would also create new
anonymous :before and :after functions for each symbol being profiled
when in fact you only need one for each hash-table.
So I modified your code a bit to define the functions just once and to
eliminate some of the ` forms which caused problems:
(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) total)))))))))
Using this code everything worked fine:
? (test-profile)
profiling (TEST-FACTORIAL)
total elapsed time 0.021 seconds
Function Count Elapsed
TEST-FACTORIAL 1000 0.011 100.00%
NIL
Regards,
Paul
On Nov 19, 2009, at 9:54 AM, Taoufik Dachraoui wrote:
> The elapsed time is in nanoseconds; in the new version of with-
> profiler the times are in
> seconds.
>
> I modified the with-profiler macro to sort the elapsed times and
> added a column to show the percentage of the elapsed times :
>
> (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 ~10,3F seconds~%" (/ (- (get-
> real-time) elapsed) 1000000000)))
> (dolist (s ',syms)
> (CCL::%UNTRACE-0 `(,s)))
> (let ((lst nil) (total 0))
> (maphash #'(lambda (k v)
> (incf total (/ (third v) 1000000000))
> (push (list k (second v) (third v)) lst))
> *profiler*)
> (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) total)))))
> ))
>
> Output example:
>
> total elapsed time 1.159 seconds
> Function Count Elapsed
> SEND-MESSAGE-TO-WINDOW 0 0.000 0.00
> LEFT-LAYOUT 0 0.000 0.00
> RROW-LAYOUT 0 0.000 0.00
> RIGHT-LAYOUT 0 0.000 0.00
> RCOLUMN-LAYOUT 0 0.000 0.00
> GET-EVENT-HANDLER 0 0.000 0.00
> %LIST 4 0.000 0.01
> CENTER-LAYOUT 4 0.000 0.01
> %LIST-SYMBOLS 12 0.000 0.03
> %GET-VFIELDS 1 0.000 0.06
> %GEN-FLET-VFIELDS 4 0.001 0.07
> %FLET-VFIELDS 1 0.001 0.08
> %VFIELDS 1 0.001 0.08
> DESTROY-CONTEXT 1 0.001 0.08
> XCREATEWINDOW 69 0.001 0.09
> %EVAL 20 0.001 0.09
> %SPLIT-ARGS 254 0.003 0.34
> RESIZE-WINDOW 69 0.003 0.37
> COLUMN-LAYOUT 11 0.005 0.65
> SPLIT-ARGS 254 0.008 1.05
> ROW-LAYOUT 16 0.008 1.13
> CLIP 27 0.023 3.06
> GETA 19185 0.172 23.17
> CREATE-WINDOW 69 0.253 34.02
> CREATE-CONTEXT 69 0.264 35.60
> NIL
> ?
>
> Taoufik
> On Nov 19, 2009, at 4:44 PM, Alexander Repenning wrote:
>
>> 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
>>
>>
>
> _______________________________________________
> Openmcl-devel mailing list
> Openmcl-devel at clozure.com
> http://clozure.com/mailman/listinfo/openmcl-devel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clozure.com/pipermail/openmcl-devel/attachments/20091119/934ab85b/attachment.htm>
More information about the Openmcl-devel
mailing list