<html><head></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; ">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.<div><br></div><div>best, Alex</div><div><br><div><div>On Nov 19, 2009, at 7:24 AM, Taoufik Dachraoui wrote:</div><br class="Apple-interchange-newline"><blockquote type="cite"><div>Hi,<br><br>I created a macro with-profiler and would like to know the <br>disadvantages of this solution<br>compared to others:<br><br>; i took the following 2 functions from ccl-1.4/tools/advice-profiler/ <br>profiler.lisp<br>; the with-profiler can be modified to return cpu-time, user-time and <br>real-time used<br>; by all profiled functions<br><br>(defun mach-timespec->nanoseconds (ts)<br> "Convert the given typespec structure into nanoseconds."<br> (+ (* 1000000000 (pref ts :mach_timespec.tv_sec))<br> (pref ts :mach_timespec.tv_nsec)))<br><br>(defun get-real-time ()<br> (let ((clock-port (make-record :clock_serv_t)))<br> (#_host_get_clock_service (#_mach_host_self) #$REALTIME_CLOCK <br>clock-port)<br> (ccl:rlet ((ts :mach_timespec))<br><span class="Apple-tab-span" style="white-space:pre"> </span> (#_clock_get_time (%get-ptr clock-port) ts)<br><span class="Apple-tab-span" style="white-space:pre"> </span> (mach-timespec->nanoseconds ts))))<br><br>(defmacro with-profiler (syms &rest body)<br> `(let ((*profiler* (make-hash-table :test #'equal)))<br> (dolist (s ',syms)<br> (setf (gethash `,s *profiler*) '(nil 0 0))<br> (CCL::%UNTRACE-0 `(,s))<br> (CCL::%TRACE-0 `((,s :before #'(lambda (f &rest vals)<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (declare (ignore vals))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (multiple-value-bind (last count elapsed) (values-list <br>(gethash f *profiler*))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (declare (ignore last))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (setf (gethash f *profiler*) (list (get-real-time) (+ 1 count) <br>elapsed))))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> :after #'(lambda (f &rest vals)<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (declare (ignore vals))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (multiple-value-bind (last count elapsed) (values-list <br>(gethash f *profiler*))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (let ((tim (get-real-time)))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> (setf (gethash f *profiler*) (list tim count (+ elapsed (- tim <br>last)))))))))<br><span class="Apple-tab-span" style="white-space:pre"> </span><span class="Apple-tab-span" style="white-space:pre"> </span> 'NIL))<br> (format t "~%profiling ~A~%" (trace))<br> (let ((elapsed (get-real-time)))<br> (eval '(progn ,@body))<br> (format t "total elapsed time ~S~%" (- (get-real-time) elapsed)))<br> (dolist (s ',syms)<br> (CCL::%UNTRACE-0 `(,s)))<br> (maphash #'(lambda (k v) (format t "function=~S count=~S <br>elapsed=~S~%" k (second v) (third v))) *profiler*)))<br><br>Tests:<br><br>? (defun fact (n) (if (= 0 n) 1 (* n (fact (- n 1)))))<br>? (defun f () (sleep 1))<br>? (defmacro foo () (progn (f) ''foo))<br>? (with-profiler (f fact)<br><span class="Apple-tab-span" style="white-space:pre"> </span>(dotimes (i 10)<br><span class="Apple-tab-span" style="white-space:pre"> </span> (f)<br><span class="Apple-tab-span" style="white-space:pre"> </span> (foo)<br><span class="Apple-tab-span" style="white-space:pre"> </span> (fact (random 100))))<br><br>profiling (FACT F)<br>total elapsed time 11003452329<br>function=FACT count=10 elapsed=268738<br>function=F count=11 elapsed=11001194423<br>NIL<br>?<br><br>Any comments on this method of profiling lisp functions are welcome<br><br>Kind regards<br>Taoufik<br><br>On Nov 18, 2009, at 5:57 PM, Matt Tenenbaum wrote:<br><br><blockquote type="cite"><br></blockquote><blockquote type="cite">Norvig's classic "Paradigms of Artificial Intelligence Programming"<br></blockquote><blockquote type="cite">has a section on instrumentation in chapter 9, including code for<br></blockquote><blockquote type="cite">profiling in a manner analogous to TRACE. In looking quickly, this<br></blockquote><blockquote type="cite">code doesn't seem to be included in the distributed source for the<br></blockquote><blockquote type="cite">book (<a href="http://norvig.com/paip/README.html">http://norvig.com/paip/README.html</a>), but you might find that<br></blockquote><blockquote type="cite">chapter helpful.<br></blockquote><blockquote type="cite"><br></blockquote><blockquote type="cite">Cheers,<br></blockquote><blockquote type="cite">-mt<br></blockquote><blockquote type="cite"><br></blockquote><blockquote type="cite">On Wed, Nov 18, 2009 at 8:36 AM, Taoufik Dachraoui<br></blockquote><blockquote type="cite"><<a href="mailto:taoufik.dachraoui@wanadoo.fr">taoufik.dachraoui@wanadoo.fr</a>> wrote:<br></blockquote><blockquote type="cite"><blockquote type="cite">Hi<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">How do I profile lisp program to know how much time each called<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">function takes<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">Regards<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">Taoufik<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">_______________________________________________<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">Openmcl-devel mailing list<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><a href="mailto:Openmcl-devel@clozure.com">Openmcl-devel@clozure.com</a><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><a href="http://clozure.com/mailman/listinfo/openmcl-devel">http://clozure.com/mailman/listinfo/openmcl-devel</a><br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite"><br></blockquote></blockquote><blockquote type="cite"><br></blockquote><br><br><br>_______________________________________________<br>Openmcl-devel mailing list<br><a href="mailto:Openmcl-devel@clozure.com">Openmcl-devel@clozure.com</a><br><a href="http://clozure.com/mailman/listinfo/openmcl-devel">http://clozure.com/mailman/listinfo/openmcl-devel</a><br></div></blockquote></div><br><div>
<span class="Apple-style-span" style="border-collapse: separate; color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; orphans: 2; text-align: auto; text-indent: 0px; text-transform: none; white-space: normal; widows: 2; word-spacing: 0px; -webkit-border-horizontal-spacing: 0px; -webkit-border-vertical-spacing: 0px; -webkit-text-decorations-in-effect: none; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0; "><span class="Apple-style-span" style="border-collapse: separate; border-spacing: 0px 0px; color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; text-align: auto; -khtml-text-decorations-in-effect: none; text-indent: 0px; -apple-text-size-adjust: auto; text-transform: none; orphans: 2; white-space: normal; widows: 2; word-spacing: 0px; "><span class="Apple-style-span" style="border-collapse: separate; border-spacing: 0px 0px; color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; text-align: auto; -khtml-text-decorations-in-effect: none; text-indent: 0px; -apple-text-size-adjust: auto; text-transform: none; orphans: 2; white-space: normal; widows: 2; word-spacing: 0px; "><span class="Apple-style-span" style="border-collapse: separate; border-spacing: 0px 0px; color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant: normal; font-weight: normal; letter-spacing: normal; line-height: normal; text-align: auto; -khtml-text-decorations-in-effect: none; text-indent: 0px; -apple-text-size-adjust: auto; text-transform: none; orphans: 2; white-space: normal; widows: 2; word-spacing: 0px; "><p style="margin: 0.0px 0.0px 0.0px 0.0px"><font face="Helvetica" size="3" style="font: 12.0px Helvetica">Prof. Alexander Repenning</font></p><p style="margin: 0.0px 0.0px 0.0px 0.0px"><br class="khtml-block-placeholder"></p><p style="margin: 0.0px 0.0px 0.0px 0.0px">University of Colorado</p><p style="margin: 0.0px 0.0px 0.0px 0.0px">Computer Science Department</p><p style="margin: 0.0px 0.0px 0.0px 0.0px">Boulder, CO 80309-430</p><p style="margin: 0.0px 0.0px 0.0px 0.0px"><br class="khtml-block-placeholder"></p><p style="margin: 0.0px 0.0px 0.0px 0.0px"><font face="Helvetica" size="3" style="font: 12.0px Helvetica">vCard: <a href="http://www.cs.colorado.edu/~ralex/AlexanderRepenning.vcf">http://www.cs.colorado.edu/~ralex/AlexanderRepenning.vcf</a></font></p><br class="Apple-interchange-newline"></span></span></span></span>
</div>
<br></div></body></html>