A better way to profile SBCL code

This is a Lisp page, written Fri Jan 18 20:01:28 PST 2008.

Previously, we described a simple method to profile selected functions in SBCL Lisp.

But what about the related task of profiling all your code? The code http://unbox.org/wisp/var/timm/08/ai/src/profile.lisp illustrates one method.

*lisp-funs*

That code contains a list of all symbols in a standard release of Common LISP and SBCL:

(defparameter *lisp-funs* '(
			    *
			    *
			    **
			    ***
			    +
			    +
			    ++
			    +++
			    -
			    -
			    /
			    /
			    //
			    ///
			    1+
			    1-
			    <
			    <=
			    =
			    >
			    >=
			    abort
			    abs
			    acons
			    acos
                 
                etc
))

(my-funs)

There is also a trick to find all the symbols in *package* user that are bound to a function (i.e. satisfy "fboundp") that aren't in "*lisp-funs*".
(defun my-funs ()
  (let ((out '()))
    (do-symbols  (s)
      (if (and (fboundp s)
	       (find-symbol  (format nil "~a" s) *package*)
	       (not (member s *lisp-funs*)))
	  (push s out)))
    out))

(watch code)

With "my-funs", we can write a "watch" macro that wraps the SBCL profiling calls:

(defmacro watch (code)
  `(progn
    (sb-profile:unprofile)
    (sb-profile:reset)
    (sb-profile:profile ,@(my-funs))
    (eval ,code)
    (sb-profile:report)
    (sb-profile:unprofile)
    t)
)

Example: (watch (main))

With all the above, then we can profile all the functions called from some high-level "(main)" function, as follows:

(watch (main))

The result is a standard SBCL profiler output. Note that, in the following, the "!" function takes 0.447/0.707 (i.e. over half) the run time. So if we are going to optimize anything, optimize "!".

CL-USER> (watch (main))
  seconds  |   consed   |   calls   |  sec/call  |  name  
------------------------------------------------------------
     0.447 |          0 |   990,001 |  0.0000005 | !
     0.105 |  6,819,840 |   170,000 |   0.000001 | EM2EFFORT
     0.073 |  6,795,264 |   170,000 |  0.0000004 | EM2RIN
     0.027 |  6,778,880 |   170,000 |  0.0000002 | EM2CIN
     0.020 |  1,585,152 |    50,000 |  0.0000004 | SF2CIN
     0.016 |  1,630,208 |    50,000 |  0.0000003 | SF2DIN
     0.012 |  6,742,016 |   170,000 |  0.0000001 | EM2DIN
     0.006 |    946,176 |    30,000 |  0.0000002 | DR2ROUT
     0.001 |          0 |        14 |   0.000067 | MAKE-R15
     0.001 |      8,192 |         1 |   0.000539 | COCOMO-DEFAULTS
     0.000 |          0 |         5 |   0.000000 | MAKE-SFS
     0.000 |          0 |         1 |   0.000000 | LINE-Y
     0.000 |          0 |        27 |   0.000000 | ?
     0.000 |          0 |         1 |   0.000000 | INIT-DB
     0.000 |          0 |         5 |   0.000000 | MAKE-R16
     0.000 |          0 |         7 |   0.000000 | MAKE-RIN+
     0.000 |  1,695,744 |    50,000 |   0.000000 | SF2EFFORT
     0.000 |          0 |         1 |   0.000000 | MAKE-R26
     0.000 |          0 |         9 |   0.000000 | MAKE-EM-
     0.000 |          0 |         6 |   0.000000 | MAKE-DIN+
     0.000 |          0 |         1 |   0.000000 | ?ONE-B
     0.000 |          0 |         1 |   0.000000 | MAKE-ONE-A
     0.000 |          0 |        27 |   0.000000 | GUESS
     0.000 |          0 |        25 |   0.000000 | ?ELT
     0.000 |          0 |         5 |   0.000000 | MAKE-DSF
     0.000 |    974,848 |    30,000 |   0.000000 | DR2DOUT
     0.000 |          0 |        34 |   0.000000 | MAKE-EM
     0.000 |          0 |        25 |   0.000000 | ?BAG
     0.000 |          0 |         6 |   0.000000 | MAKE-DR
     0.000 |          0 |        10 |   0.000000 | MAKE-RIN-
     0.000 |          0 |         5 |   0.000000 | MAKE-RSF
     0.000 |          0 |         3 |   0.000000 | ?DR
     0.000 |          0 |         1 |   0.000000 | POINT-TO-LINE
     0.000 |          0 |         3 |   0.000000 | MAKE-RDR
     0.000 |          0 |         1 |   0.000000 | DEMO456
     0.000 |          0 |         1 |   0.000000 | MAKE-LINE
     0.000 |          0 |         3 |   0.000000 | MAKE-R25
     0.000 |          0 |         3 |   0.000000 | MAKE-DDR
     0.000 |          0 |         5 |   0.000000 | MAKE-CSF
     0.000 |          0 |        10 |   0.000000 | MAKE-SF
     0.000 |          0 |         6 |   0.000000 | MAKE-CIN+
     0.000 |          0 |        11 |   0.000000 | MAKE-CIN-
     0.000 |          0 |        28 |   0.000000 | GETA
     0.000 |  1,482,752 |    50,000 |   0.000000 | SF2RIN
     0.000 |          0 |         5 |   0.000000 | ?SF
     0.000 |      8,192 |        17 |   0.000000 | ?EM
     0.000 |          0 |         8 |   0.000000 | MAKE-EM+
     0.000 |          0 |         2 |   0.000000 | MAKE-NUM
     0.000 |          0 |         1 |   0.000000 | ?ONE-A
     0.000 |    958,464 |    30,000 |   0.000000 | DR2COUT
     0.000 |          0 |         3 |   0.000000 | MAKE-CODR
     0.000 |          0 |         1 |   0.000000 | MAKE-ONE-B
     0.000 | 24,076,288 |         1 |   0.000000 | DEMO456A
     0.000 |          0 |        25 |   0.000000 | COCO
     0.000 |          0 |         2 |   0.000000 | MAKE-R36
     0.000 |          0 |        11 |   0.000000 | MAKE-DIN-
     0.000 |          0 |         1 |   0.000000 | MAKE-DB
     0.000 |    155,648 |    10,124 |   0.000000 | MY-RANDOM
------------------------------------------------------------
     0.707 | 60,657,664 | 1,970,493 |            | Total
 

cs472 / cs572

AI and advanced AI techniques. Spring 2008. LCSEE, WVU

Venn diagram with three overlapping circles Home | News | Syllabus | Project
Lectures | LISP | EMACS | Fun
Links | Site map | Contact
NOVA
    Creative Commons License
    © 2007, 2008
     Tim Menzies