[Openmcl-devel] Profiling lisp code
Taoufik Dachraoui
taoufik.dachraoui at wanadoo.fr
Thu Nov 19 11:25:38 PST 2009
Paul,
I like your solution better than mine; for me everything works fine
because I created *profiler*
using defvar.
But I like better your solution because you do not need a global
variable.
The first time I wrote the profiler I used flet to define the before
and after functions and
it did not work correctly; I certanily did a mistake and did not
bother to search the error.
Kind regards
Taoufik
On Nov 19, 2009, at 7:41 PM, Paul Krueger wrote:
> 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/aef6932e/attachment.htm>
More information about the Openmcl-devel
mailing list