SBCL's statistical profiler does not show an entry for each function called

Question

I am using the statistical profiler of SBCL to profile these functions:

(defun fact-rec (n)
  (if (zerop n)
      1
      (* n (fact-rec (1- n)))))

(defun fact-call (n)
  (fact-rec n))

(defun fact-iter (n)
  (loop :with accu = 1
    :for i :upfrom 2 :to n
    :doing (setf accu (* i accu))
    :finally (return accu)))

(defun fact-opti-iter (n)
  (let ((accu 1))
    (tagbody
     loop
       (unless (zerop n)
         (setf accu (* n accu))
         (decf n)
         (go loop)))
    accu))

In order to evaluate the weight of the recursive version, I defined a function fact-call that stays on the stack below all the fact-rec calls so that it can be monitored correctly. Here is my profiling code:

(sb-sprof:profile-call-counts 'fact-rec 'fact-call 'fact-iter 'fact-opti-iter)
(sb-sprof:with-profiling (:max-samples 1000
                   :loop nil
                   :report :flat)
       (dotimes (i 1500)
         (fact-call i)
         (fact-iter i)
         (fact-opti-iter i)))

Proceeding that way ensures that fact-rec is never directly called so if it appears on the profiler's report, then it has necessarily been called by fact-call. But here is the report I get:

Profiler sample vector full (70 traces / 10000 samples), doubling the size
Profiler sample vector full (133 traces / 20000 samples), doubling the size

Number of samples:   195
Sample interval:     0.01 seconds
Total sampling time: 1.9499999 seconds
Number of cycles:    0
Sampled threads:
 #

           Self        Total        Cumul
  Nr  Count     %  Count     %  Count     %    Calls  Function
------------------------------------------------------------------------
   1    193  99.0    193  99.0    193  99.0        -  SB-BIGNUM:MULTIPLY-BIGNUM-AND-FIXNUM
   2      1   0.5    195 100.0    194  99.5        -  SB-KERNEL:TWO-ARG-*
   3      1   0.5      1   0.5    195 100.0        -  SB-BIGNUM::%NORMALIZE-BIGNUM
   4      0   0.0    195 100.0    195 100.0        -  "Unknown component: #x100317AB30"
   5      0   0.0    195 100.0    195 100.0        -  SB-INT:SIMPLE-EVAL-IN-LEXENV
   6      0   0.0    195 100.0    195 100.0        -  EVAL
   7      0   0.0    195 100.0    195 100.0        -  SWANK::EVAL-REGION
   8      0   0.0    195 100.0    195 100.0        -  (LAMBDA NIL :IN SWANK-REPL::REPL-EVAL)
   9      0   0.0    195 100.0    195 100.0        -  SWANK-REPL::TRACK-PACKAGE
  10      0   0.0    195 100.0    195 100.0        -  SWANK::CALL-WITH-RETRY-RESTART
  11      0   0.0    195 100.0    195 100.0        -  SWANK::CALL-WITH-BUFFER-SYNTAX
  12      0   0.0    195 100.0    195 100.0        -  SWANK-REPL::REPL-EVAL
  13      0   0.0    195 100.0    195 100.0        -  SWANK:EVAL-FOR-EMACS
  14      0   0.0    195 100.0    195 100.0        -  SWANK::PROCESS-REQUESTS
  15      0   0.0    195 100.0    195 100.0        -  (LAMBDA NIL :IN SWANK::HANDLE-REQUESTS)
  16      0   0.0    195 100.0    195 100.0        -  SWANK/SBCL::CALL-WITH-BREAK-HOOK
  17      0   0.0    195 100.0    195 100.0        -  (FLET SWANK/BACKEND:CALL-WITH-DEBUGGER-HOOK :IN "/Users/vleo/quicklisp/dists/quicklisp/software/slime-v2.19/swank/sbcl.lisp")
  18      0   0.0    195 100.0    195 100.0        -  SWANK::CALL-WITH-BINDINGS
  19      0   0.0    195 100.0    195 100.0        -  SWANK::HANDLE-REQUESTS
  20      0   0.0    195 100.0    195 100.0        -  (LABELS SWANK/SBCL::RUN :IN SWANK/BACKEND:ADD-FD-HANDLER)
  21      0   0.0    195 100.0    195 100.0        -  SB-IMPL::SUB-SUB-SERVE-EVENT
  22      0   0.0    195 100.0    195 100.0        -  SB-IMPL::SUB-SERVE-EVENT
  23      0   0.0    195 100.0    195 100.0        -  SB-SYS:WAIT-UNTIL-FD-USABLE
  24      0   0.0    195 100.0    195 100.0        -  SB-IMPL::REFILL-INPUT-BUFFER
  25      0   0.0    195 100.0    195 100.0        -  SB-IMPL::INPUT-CHAR/UTF-8
  26      0   0.0    195 100.0    195 100.0        -  (LAMBDA (&REST REST) :IN SB-IMPL::GET-EXTERNAL-FORMAT)
  27      0   0.0    195 100.0    195 100.0        -  READ-CHAR
  28      0   0.0    195 100.0    195 100.0        -  SB-IMPL::%READ-PRESERVING-WHITESPACE
  29      0   0.0    195 100.0    195 100.0        -  READ
  30      0   0.0    195 100.0    195 100.0        -  SB-IMPL::REPL-READ-FORM-FUN
  31      0   0.0    195 100.0    195 100.0        -  SB-IMPL::REPL-FUN
  32      0   0.0    195 100.0    195 100.0        -  (LAMBDA NIL :IN SB-IMPL::TOPLEVEL-REPL)
  33      0   0.0    195 100.0    195 100.0        -  SB-IMPL::%WITH-REBOUND-IO-SYNTAX
  34      0   0.0    195 100.0    195 100.0        -  SB-IMPL::TOPLEVEL-REPL
  35      0   0.0    195 100.0    195 100.0        -  SB-IMPL::TOPLEVEL-INIT
  36      0   0.0    195 100.0    195 100.0        -  (FLET #:WITHOUT-INTERRUPTS-BODY-74 :IN SAVE-LISP-AND-DIE)
  37      0   0.0    195 100.0    195 100.0        -  (LABELS SB-IMPL::RESTART-LISP :IN SAVE-LISP-AND-DIE)
  38      0   0.0     69  35.4    195 100.0     1500  FACT-OPTI-ITER
  39      0   0.0     65  33.3    195 100.0  1125750  FACT-REC
  40      0   0.0     61  31.3    195 100.0     1500  FACT-ITER
------------------------------------------------------------------------
          0   0.0                                     elsewhere

There is no mention of fact-call even though it has certainly been called. Moreover there is an entry for fact-rec. If fact-call's call is deeper in the stack and fact-rec is recorded, shouldn't it be recorded as well?

Thank you

Rainer Joswig Rainer Joswig · Accepted Answer · 2017-05-19T17:54:33

Are you sure that the call to fact-call stays on the stack? Did you check that?

The SBCL compiler can do TCO (tail call optimization). The function fact-call calls fact-rec in tail position. This function call can be replaced by a jump, reusing the current stack frame.

TCO

Let's modify fact-rec, so that it calls break and we can look at the stack:

(defun fact-rec (n)
  (if (zerop n)
      (progn (break) 1)
    (* n (fact-rec (1- n)))))

(defun fact-call (n)
  (fact-rec n))       ; tail call to FACT-REC

Let's call it from test:

(defun test ()
 (fact-call 4))

The backtrace looks like this - no fact-call.

Backtrace:
  0: (FACT-REC 0)
  1: (FACT-REC 1)
  2: (FACT-REC 2)
  3: (FACT-REC 3)
  4: (FACT-REC 4)

No TCO

Now we tell the SBCL compiler to not use TCO inside fact-call:

(defun fact-call (n)
  (declare (optimize (debug 3)))    ; debug level 3 does no TCO
  (fact-rec n))

Now this is the call stack:

Backtrace:
  0: (FACT-REC 0)
  1: (FACT-REC 1)
  2: (FACT-REC 2)
  3: (FACT-REC 3)
  4: (FACT-REC 4)
  5: (FACT-CALL 4)

As you can see, the call to FACT-CALL stays on the stack.

SBCL's statistical profiler does not show an entry for each function called

1 Answers