A poor man's Common Lisp profiler (08 Mar 2016)

Alex's original code used quite some Lisp magic, including the little-known symbol-function which I elaborated about long time ago. But the code did not quite work yet. I gladly took the challenge. and ended up with a few lines of Lisp code which could profile (almost) any Lisp function in the system. The technique I used was to wrap the original function definition in a lambda closure. That closure is then installed using symbol-function.

(in-package :clausbrod.de)
(export '(profile-function unprofile-function list-profiling-results))

(let ((profile-hashtable (make-hash-table)))
  (defun profile-function(func)
    "Instrument function for profiling"

    ;; check if symbol-plist already contains profiler flag
    (unless (get func :profile-original-symbol-function)
      (let ((original-symbol-function (symbol-function func)))
   (when original-symbol-function
     (setf (get func :profile-original-symbol-function) original-symbol-function) ;; mark as profiled

     ;; install profiler code
     (setf (symbol-function func)
      (lambda(&rest r)
        (let ((start-time (f2::seconds-since-1970)))
          (unwind-protect
         (if r
             (apply original-symbol-function r)
           (funcall original-symbol-function))
            (let ((execution-time (- (f2::seconds-since-1970) start-time))
             (accum (gethash func profile-hashtable)))
         (if accum
             (setf (gethash func profile-hashtable) (+ accum execution-time))
           (setf (gethash func profile-hashtable) execution-time))
         (format *standard-output* "~%Execution time for ~S: ~,10F~%" func execution-time))))))
     ))))

  (defun unprofile-function(func)
    "Remove profiling instrumentation for function"
    (let ((original-symbol-function (get func :profile-original-symbol-function)))
      (when (remprop func :profile-original-symbol-function)
   (setf (symbol-function func) original-symbol-function))))

  (defun list-profiling-results()
    "List profiling results in order of decreasing accumulated execution times"
    (format *standard-output* "~%Accumulated execution times:~%")
    (let (table-as-list)
      (maphash (lambda(k v) (push (cons k v) table-as-list)) profile-hashtable)
      (dolist (pair (sort table-as-list #'> :key #'cdr))
   (format *standard-output* "~S:  ~,10F~%" (car pair) (cdr pair)))))
  )

(f2::win-open-console-window)
(setf si::*enter-break-handler* t)
(use-fast-links nil)

There are other profilers out there for Common Lisp, but it is not always straightforward to make them work in CoCreate Modeling which implements a subset of CLtL1 only. So who knows, maybe someone out there will actually find this useful!

To profile a function:

  (clausbrod.de:profile-function 'my-function)

Now execute my-function at your heart's content. Every time the function is called, the profiler measures its execution time. When the test session is completed, accumulated execution times can be listed as follows:

  (clausbrod.de:list-profiling-results)

And here is how to profile all functions in a given Lisp package:

  (do-external-symbols (s (find-package "FOO"))
    (when (function s)
      (clausbrod.de:profile-function s)))

My implementation differs almost entirely from Alex' version, which allows me to call it my own, but of course I owe thanks to Alex for starting the discussion in the forum and posting his original inspirational code!

The code is now available as a Github project, see https://github.com/clausb/lisp-profiler. There is even a simple GUI dialog on top of the low-level profiling code:

The version of the code shown above uses a SolidDesigner-specific way of getting the current time in high precision. The improved version in the Github project should work in other Lisp dialects as well. Fingers crossed.