[Openmcl-devel] Profiling lisp code
Taoufik Dachraoui
taoufik.dachraoui at wanadoo.fr
Thu Nov 19 07:54:33 PST 2009
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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.clozure.com/pipermail/openmcl-devel/attachments/20091119/9691f0b1/attachment.htm>
More information about the Openmcl-devel
mailing list