contrib/sb-sprof/sb-sprof.texinfo

   1 @cindex Profiling, statistical
   2
   3 The @code{sb-sprof} module, loadable by
   4 @lisp
   5 (require :sb-sprof)
   6 @end lisp
   7 provides an alternate profiler which works by taking samples of the
   8 program execution at regular intervals, instead of instrumenting
   9 functions like @code{sb-profile:profile} does. You might find
  10 @code{sb-sprof} more useful than the deterministic profiler when profiling
  11 functions in the @code{common-lisp}-package, SBCL internals, or code
  12 where the instrumenting overhead is excessive.
  13
  14 Additionally @code{sb-sprof} includes a limited deterministic profiler
  15 which can be used for reporting the amounts of calls to some functions
  16 during
  17
  18 @subsection Example Usage
  19
  20 @lisp
  21 (in-package :cl-user)
  22
  23 (require :sb-sprof)
  24
  25 (declaim (optimize speed))
  26
  27 (defun cpu-test-inner (a i)
  28   (logxor a
  29           (* i 5)
  30           (+ a i)))
  31
  32 (defun cpu-test (n)
  33   (let ((a 0))
  34     (dotimes (i (expt 2 n) a)
  35       (setf a (cpu-test-inner a i)))))
  36
  37 ;;;; CPU profiling
  38
  39 ;;; Take up to 1000 samples of running (CPU-TEST 26), and give a flat
  40 ;;; table report at the end. Profiling will end one the body has been
  41 ;;; evaluated once, whether or not 1000 samples have been taken.
  42 (sb-sprof:with-profiling (:max-samples 1000
  43                           :report :flat
  44                           :loop nil)
  45   (cpu-test 26))
  46
  47 ;;; Record call counts for functions defined on symbols in the CL-USER
  48 ;;; package.
  49 (sb-sprof:profile-call-counts "CL-USER")
  50
  51 ;;; Take 1000 samples of running (CPU-TEST 24), and give a flat
  52 ;;; table report at the end. The body will be re-evaluated in a loop
  53 ;;; until 1000 samples have been taken. A sample count will be printed
  54 ;;; after each iteration.
  55 (sb-sprof:with-profiling (:max-samples 1000
  56                           :report :flat
  57                           :loop t
  58                           :show-progress t)
  59   (cpu-test 24))
  60
  61 ;;;; Allocation profiling
  62
  63 (defun foo (&rest args)
  64   (mapcar (lambda (x) (float x 1d0)) args))
  65
  66 (defun bar (n)
  67   (declare (fixnum n))
  68   (apply #'foo (loop repeat n collect n)))
  69
  70 (sb-sprof:with-profiling (:max-samples 10000
  71                           :mode :alloc
  72                           :report :flat)
  73   (bar 1000))
  74 @end lisp
  75
  76 @subsection Output
  77
  78 The flat report format will show a table of all functions that the
  79 profiler encountered on the call stack during sampling, ordered by the
  80 number of samples taken while executing that function.
  81
  82 @lisp
  83            Self        Total        Cumul
  84   Nr  Count     %  Count     %  Count     %    Calls  Function
  85 ------------------------------------------------------------------------
  86    1     69  24.4     97  34.3     69  24.4 67108864  CPU-TEST-INNER
  87    2     64  22.6     64  22.6    133  47.0        -  SB-VM::GENERIC-+
  88    3     39  13.8    256  90.5    172  60.8        1  CPU-TEST
  89    4     31  11.0     31  11.0    203  71.7        -  SB-KERNEL:TWO-ARG-XOR
  90 @end lisp
  91
  92 For each function, the table will show three absolute and relative
  93 sample counts. The Self column shows samples taken while directly
  94 executing that function. The Total column shows samples taken while
  95 executing that function or functions called from it (sampled to a
  96 platform-specific depth). The Cumul column shows the sum of all
  97 Self columns up to and including that line in the table.
  98
  99 Additionally the Calls column will record the amount of calls that were
 100 made to the function during the profiling run. This value will only
 101 be reported for functions that have been explicitly marked for call counting
 102 with @code{profile-call-counts}.
 103
 104 The profiler also hooks into the disassembler such that instructions which
 105 have been sampled are annotated with their relative frequency of
 106 sampling.  This information is not stored across different sampling
 107 runs.
 108
 109 @lisp
 110 ;      6CF:       702E             JO L4              ; 6/242 samples
 111 ;      6D1:       D1E3             SHL EBX, 1
 112 ;      6D3:       702A             JO L4
 113 ;      6D5: L2:   F6C303           TEST BL, 3         ; 2/242 samples
 114 ;      6D8:       756D             JNE L8
 115 ;      6DA:       8BC3             MOV EAX, EBX       ; 5/242 samples
 116 ;      6DC: L3:   83F900           CMP ECX, 0         ; 4/242 samples
 117 @end lisp
 118
 119 @subsection Platform support
 120
 121 This module is known not to work consistently on the Alpha platform,
 122 for technical reasons related to the implementation of a machine
 123 language idiom for marking sections of code to be treated as atomic by
 124 the garbage collector;  However, it should work on other platforms,
 125 and the deficiency on the Alpha will eventually be rectified.
 126
 127 Allocation profiling is only supported on SBCL builds that use
 128 the generational garbage collector. Tracking of call stacks at a
 129 depth of more than two levels is only supported on x86 and x86-64.
 130
 131 @subsection Macros
 132
 133 @include macro-sb-sprof-with-profiling.texinfo
 134 @include macro-sb-sprof-with-sampling.texinfo
 135
 136 @subsection Functions
 137
 138 @include fun-sb-sprof-report.texinfo
 139
 140 @include fun-sb-sprof-reset.texinfo
 141
 142 @include fun-sb-sprof-start-profiling.texinfo
 143
 144 @include fun-sb-sprof-stop-profiling.texinfo
 145
 146 @include fun-sb-sprof-profile-call-counts.texinfo
 147
 148 @include fun-sb-sprof-unprofile-call-counts.texinfo
 149
 150 @subsection Variables
 151
 152 @include var-sb-sprof-star-max-samples-star.texinfo
 153
 154 @include var-sb-sprof-star-sample-interval-star.texinfo
 155
 156 @subsection Credits
 157
 158 @code{sb-sprof} is an SBCL port, with enhancements, of Gerd
 159 Moellmann's statistical profiler for CMUCL.