CODEWITHSUNDEEP
profilingcommon-lisp
davypough
davypough

Reputation: 1941

Profiling Functions in the :CL Package

In SBCL is there a way to profile functions in "COMMON-LISP" package? I'm basically looking for a way to reliably compare the run times of some built-in functions. For example, could the following function

(defun doit ()
  (dotimes (i 10000000)
    (make-list 10 :initial-element 0)
    (list 0 0 0 0 0 0 0 0 0 0)))

be used to compare the relative efficiency of make-list and list, if they were profiled? (Note that the assembly code for each function is somewhat different.) My attempts at profiling in :cl bring up the low-level debugger.

Another approach using sb-ext:get-time-of-day (presumably accurate to 1 usec) appears to give highly variable results:

(multiple-value-bind (* usec1) (sb-ext:get-time-of-day)
  (dotimes (i 100000000)
    (make-list 10 :initial-element 0))
  (multiple-value-bind (* usec2) (sb-ext:get-time-of-day)
    (dotimes (i 100000000)
      (list 0 0 0 0 0 0 0 0 0 0))
    (multiple-value-bind (* usec3) (sb-ext:get-time-of-day)
      (- (- usec2 usec1) (- usec3 usec2)))))

Thanks for any additional advice.

EDIT: Here's another possible approach to teasing out small timing differences using the Profiler. The example again compares make-list with list, and produces results that are fairly reliable across multiple runs.

* (defun run-make-list ()
    (dotimes (i 10000000000)
      (make-list 10 :initial-element 0)))
RUN-MAKE-LIST
* (defun run-list()
    (dotimes (i 10000000000)
      (list 0 0 0 0 0 0 0 0 0 0)))
RUN-LIST
* (defun compare ()
    (gc)
    (run-make-list)
    (run-list))
COMPARE
* (profile "COMMON-LISP-USER")
* (compare)
NIL
* (report)
measuring PROFILE overhead..done
  seconds  |     gc     | consed | calls |  sec/call  |  name
----------------------------------------------------
     6.532 |      0.000 |      0 |     1 |   6.532000 | RUN-LIST
     6.406 |      0.000 |      0 |     1 |   6.406000 | RUN-MAKE-LIST
     0.000 |      0.000 |      0 |     1 |   0.000000 | COMPARE
----------------------------------------------------
    12.938 |      0.000 |      0 |     3 |            | Total

estimated total profiling overhead: 0.00 seconds
overhead estimation parameters:
  0.0s/call, 1.4379999e-6s total profiling, 5.98e-7s internal profiling
*

However, I'm not sure whether to believe the results. The target comparison might be swamped by the loop overhead.

Upvotes: 1

Views: 370

Answers (3)

automaton
automaton

Reputation: 1121

SBCL has a statistical profiler, and the manual states:

You might find sb-sprof more useful than the deterministic profiler when profiling functions in the common-lisp-package, SBCL internals, or code where the instrumenting overhead is excessive.

Upvotes: 3

Svante
Svante

Reputation: 51521

You can use time:

(time (some-form))

This runs (some-form) and prints timing information. The results will be just as variable as those you obtained, however.

The problem is that our computers do a lot of things at the same time. Your experiment might be affected by your computer checking mail, some other process having a garbage collection, your own process having a garbage collection, the network reconnecting, phase of the moon etc.

Sometimes, you can at least make your own process have more consistent timing by starting each experiment with a (gc).

Upvotes: 4

Simeon Ikudabo
Simeon Ikudabo

Reputation: 2190

Try the time function:

(time(defun doit ()
    (dotimes (i 10000000)
      (make-list 10 :initial-element 0)
      (list 0 0 0 0 0 0 0 0 0 0))))

Upvotes: 0

Related Questions