0.6.12.49:
[sbcl.git] / src / code / profile.lisp
index d52c13c..524b5fd 100644 (file)
 (declaim (inline get-internal-ticks))
 (defun get-internal-ticks () (get-internal-run-time))
 \f
-;;;; PCOUNTER
-
-;;; a PCOUNTER is used to represent an unsigned integer quantity which
-;;; can grow bigger than a fixnum, but typically does so, if at all,
-;;; in many small steps, where we don't want to cons on every step.
-;;; (Total system consing, time spent in a profiled function, and
-;;; bytes consed in a profiled function are all examples of such
-;;; quantities.)
-(defstruct (pcounter (:copier nil))
-  (integer 0);; :type unsigned-byte)
-  (fixnum 0));; :type (and fixnum unsigned-byte)))
-
-;;;(declaim (ftype (function (pcounter unsigned-byte) pcounter) incf-pcounter))
-;;;(declaim (inline incf-pcounter)) ; FIXME: maybe inline when more stable
-(defun incf-pcounter (pcounter delta)
-  (aver (typep delta 'unsigned-byte))
-  (let ((sum (+ (pcounter-fixnum pcounter) delta)))
-    (aver (typep sum 'unsigned-byte))
-    ;;(declare (type unsigned-byte sum))
-    (cond ((typep sum 'fixnum)
-          (setf (pcounter-fixnum pcounter) sum))
-         (t
-          (incf (pcounter-integer pcounter) sum)
-          (setf (pcounter-fixnum pcounter) 0))))
-  pcounter)
-
-(declaim (ftype (function (pcounter) integer) pcounter->integer))
-;;;(declaim (inline pcounter->integer)) ; FIXME: maybe inline when more stable
-(defun pcounter->integer (pcounter)
-  (+ (pcounter-integer pcounter)
-     (pcounter-fixnum pcounter)))
-\f
-;;;; operations on (OR PCOUNTER FIXNUM)
-;;;;
-;;;; When we don't want to cons a PCOUNTER unless we're forced to, we
-;;;; start with a FIXNUM counter and only create a PCOUNTER if the
-;;;; FIXNUM overflows.
-
-(declaim (ftype (function ((or pcounter fixnum) integer) (or pcounter fixnum)) %incf-pcounter-or-fixnum))
-;;;(declaim (inline %incf-pcounter-or-fixnum)) ; FIXME: maybe inline when more stable
-(defun %incf-pcounter-or-fixnum (x delta)
-  (etypecase x
-    (fixnum
-     (let ((sum (+ x delta)))
-       (if (typep sum 'fixnum)
-          sum
-          (make-pcounter :integer sum))))
-    (pcounter
-     (incf-pcounter x delta))))
-  
-(define-modify-macro incf-pcounter-or-fixnum (delta) %incf-pcounter-or-fixnum)
-
-;;; Trade off space for execution time by handling the common fast
-;;; (TYPEP DELTA 'FIXNUM) case inline and only calling generic
-;;; arithmetic as a last resort.
-(defmacro fastbig-incf-pcounter-or-fixnum (x delta)
-  (let ((delta-sym (gensym "DELTA")))
-    `(let ((,delta-sym ,delta))
-       (aver (typep ,delta-sym 'unsigned-byte))
-       ;;(declare (type unsigned-byte ,delta-sym))
-       (if (typep ,delta-sym 'fixnum)
-          (incf-pcounter-or-fixnum ,x ,delta)
-          (incf-pcounter-or-fixnum ,x ,delta)))))
-
-(declaim (ftype (function ((or pcounter fixnum)) integer) pcounter-or-fixnum->integer))
-(declaim (maybe-inline pcounter-or-fixnum->integer))
-(defun pcounter-or-fixnum->integer (x)
-  (etypecase x
-    (fixnum x)
-    (pcounter (pcounter->integer x))))
-\f
 ;;;; implementation-dependent interfaces
 
 #|
 (defvar *enclosed-profiles* 0)
 (declaim (type (or pcounter fixnum) *enclosed-profiles*))
 
+;;; the encapsulated function we're currently computing profiling data
+;;; for, recorded so that we can detect the problem of
+;;; PROFILE-computing machinery calling a function which has itself
+;;; been PROFILEd
+(defvar *computing-profiling-data-for*)
+
 ;;; the components of profiling overhead
 (defstruct (overhead (:copier nil))
   ;; the number of ticks a bare function call takes. This is
   (total (required-argument) :type single-float :read-only t))
 (defvar *overhead*)
 (declaim (type overhead *overhead*))
+(makunbound '*overhead*) ; in case we reload this file when tweaking
 \f
 ;;;; profile encapsulations
 
 ;;; inline.
 (defmacro fastbig- (x y)
   (once-only ((x x) (y y))
-    `(if (and (typep ,x 'fixnum)
-             (typep ,y 'fixnum))
+    `(if (and (typep ,x '(and fixnum unsigned-byte))
+             (typep ,y '(and fixnum unsigned-byte)))
+        ;; special case: can use fixnum arithmetic and be guaranteed
+        ;; the result is also a fixnum
         (- ,x ,y)
+        ;; general case
         (- ,x ,y))))
 (defmacro fastbig-1+ (x)
   (once-only ((x x))
      ;; ENCAPSULATION-FUN
      (lambda (sb-c:&more arg-context arg-count)
        (declare (optimize speed safety))
+       ;; Make sure that we're not recursing infinitely.
+       (when (boundp '*computing-profiling-data-for*)
+        (unprofile-all) ; to avoid further recursion
+        (error "~@<When computing profiling data for ~S, the profiled function ~S was called. To get out of this infinite recursion, all functions have been unprofiled. (Since the profiling system evidently uses ~S in its computations, it looks as though it's a bad idea to profile it.)~:@>"
+               *computing-profiling-data-for*
+               encapsulated-fun
+               encapsulated-fun))
        ;; FIXME: Probably when this is stable, we should optimize (SAFETY 0).
        (fastbig-incf-pcounter-or-fixnum count 1)
        (let ((dticks 0)
             (dconsing 0)
             (inner-enclosed-profiles 0))
-        ;;(declare (type unsigned-byte dticks dconsing))
-        ;;(declare (type unsigned-byte inner-enclosed-profiles))
+        (declare (type unsigned-byte dticks dconsing))
+        (declare (type unsigned-byte inner-enclosed-profiles))
         (aver (typep dticks 'unsigned-byte))
         (aver (typep dconsing 'unsigned-byte))
         (aver (typep inner-enclosed-profiles 'unsigned-byte))
         (multiple-value-prog1
-            (let ((start-ticks (get-internal-ticks))
-                  ;; KLUDGE: We add (THE UNSIGNED-BYTE ..) wrappers
-                  ;; around GET-BYTES-CONSED because as of
-                  ;; sbcl-0.6.4, at the time that the FTYPE of
-                  ;; GET-BYTES-CONSED is DECLAIMed, the
-                  ;; cross-compiler's type system isn't mature enough
-                  ;; to do anything about it. -- WHN 20000503
-                  (start-consing (the unsigned-byte (get-bytes-consed)))
-                  (*enclosed-ticks* 0)
-                  (*enclosed-consing* 0)
-                  (*enclosed-profiles* 0))
+            (let* ((start-ticks (get-internal-ticks))
+                   (*enclosed-ticks* 0)
+                   (*enclosed-consing* 0)
+                   (*enclosed-profiles* 0)
+                   (nbf-pcounter *n-bytes-freed-or-purified-pcounter*)
+                   ;; Typically NBF-PCOUNTER will represent a bignum.
+                   ;; In general we don't want to cons up a new
+                   ;; bignum for every encapsulated call, so instead
+                   ;; we keep track of the PCOUNTER internals, so
+                   ;; that as long as we only cons small amounts,
+                   ;; we'll almost always just do fixnum arithmetic.
+                   ;; (And for encapsulated functions which cons
+                   ;; large amounts, then a single extra consed
+                   ;; bignum tends to be proportionally negligible.)
+                   (nbf0-integer (pcounter-integer nbf-pcounter))
+                   (nbf0-fixnum (pcounter-fixnum nbf-pcounter))
+                   (dynamic-usage-0 (sb-kernel:dynamic-usage)))
               (declare (inline pcounter-or-fixnum->integer))
               (multiple-value-prog1
                   (multiple-value-call encapsulated-fun
                                        (sb-c:%more-arg-values arg-context
                                                               0
                                                               arg-count))
-                (setf dticks (fastbig- (get-internal-ticks) start-ticks)
-                      dconsing (fastbig- (the unsigned-byte
-                                              (get-bytes-consed))
-                                         start-consing))
-                (setf inner-enclosed-profiles
-                      (pcounter-or-fixnum->integer *enclosed-profiles*))
-                (when (minusp dticks) ; REMOVEME
-                  (error "huh? (GET-INTERNAL-TICKS)=~S START-TICKS=~S"
-                         (get-internal-ticks) start-ticks))
-                (aver (not (minusp dconsing))) ; REMOVEME
-                (aver (not (minusp inner-enclosed-profiles))) ; REMOVEME
-                (let ((net-dticks (fastbig- dticks *enclosed-ticks*)))
-                  (when (minusp net-dticks) ; REMOVEME
-                    (error "huh? DTICKS=~S, *ENCLOSED-TICKS*=~S"
-                           dticks *enclosed-ticks*))
-                  (fastbig-incf-pcounter-or-fixnum ticks net-dticks))
-                (let ((net-dconsing (fastbig- dconsing *enclosed-consing*)))
-                  (when (minusp net-dconsing) ; REMOVEME
-                    (error "huh? DCONSING=~S, *ENCLOSED-CONSING*=~S"
-                           dticks *enclosed-ticks*))
-                  (fastbig-incf-pcounter-or-fixnum consing net-dconsing))
-                (fastbig-incf-pcounter-or-fixnum profiles
-                                                 inner-enclosed-profiles)))
+                (let ((*computing-profiling-data-for* encapsulated-fun)
+                      (dynamic-usage-1 (sb-kernel:dynamic-usage)))
+                  (setf dticks (fastbig- (get-internal-ticks) start-ticks))
+                  (setf dconsing
+                        (if (and (eq (pcounter-integer nbf-pcounter)
+                                     nbf0-integer)
+                                 (eq (pcounter-fixnum nbf-pcounter)
+                                     nbf0-fixnum))
+                            ;; common special case where we can avoid
+                            ;; bignum arithmetic
+                            (- dynamic-usage-1
+                               dynamic-usage-0)
+                            ;; general case
+                            (- (get-bytes-consed)
+                               nbf0-integer
+                               nbf0-fixnum
+                               dynamic-usage-0)))
+                  (setf inner-enclosed-profiles
+                        (pcounter-or-fixnum->integer *enclosed-profiles*))
+                  (let ((net-dticks (fastbig- dticks *enclosed-ticks*)))
+                    (fastbig-incf-pcounter-or-fixnum ticks net-dticks))
+                  (let ((net-dconsing (fastbig- dconsing *enclosed-consing*)))
+                    (fastbig-incf-pcounter-or-fixnum consing net-dconsing))
+                  (fastbig-incf-pcounter-or-fixnum profiles
+                                                   inner-enclosed-profiles))))
           (fastbig-incf-pcounter-or-fixnum *enclosed-ticks* dticks)
           (fastbig-incf-pcounter-or-fixnum *enclosed-consing* dconsing)
           (fastbig-incf-pcounter-or-fixnum *enclosed-profiles*
                                             inner-enclosed-profiles)))))
      ;; READ-STATS-FUN
      (lambda ()
-       (format t "/entering READ-STATS-FUN ~S ~S ~S ~S~%"
-              count ticks consing profiles) ; REMOVEME (and M-V-PROG1 below)
-       (multiple-value-prog1
-          (values (pcounter-or-fixnum->integer count)
-                  (pcounter-or-fixnum->integer ticks)
-                  (pcounter-or-fixnum->integer consing)
-                  (pcounter-or-fixnum->integer profiles))
-        (print "/returning from READ-STATS-FUN")))
+       (values (pcounter-or-fixnum->integer count)
+              (pcounter-or-fixnum->integer ticks)
+              (pcounter-or-fixnum->integer consing)
+              (pcounter-or-fixnum->integer profiles)))
      ;; CLEAR-STATS-FUN
      (lambda ()
        (setf count 0
     (max raw-compensated 0.0)))
 
 (defun report ()
-  "Report results from profiling. The results are
-approximately adjusted for profiling overhead, but when RAW is true
-the unadjusted results are reported. The compensation may be somewhat
-inaccurate when bignums are involved in runtime calculation, as in
-a very-long-running Lisp process."
+  "Report results from profiling. The results are approximately adjusted
+for profiling overhead. The compensation may be rather inaccurate when
+bignums are involved in runtime calculation, as in a very-long-running
+Lisp process."
   (declare #.*optimize-external-despite-byte-compilation*)
   (unless (boundp '*overhead*)
     (setf *overhead*
@@ -499,7 +448,14 @@ a very-long-running Lisp process."
 ;;;; overhead estimation
 
 ;;; We average the timing overhead over this many iterations.
-(defconstant +timer-overhead-iterations+ 50000)
+;;;
+;;; (This is a variable, not a constant, so that it can be set in
+;;; .sbclrc if desired. Right now, that's an unsupported extension
+;;; that I (WHN) use for my own experimentation, but it might
+;;; become supported someday. Comments?)
+(declaim (type unsigned-byte *timer-overhead-iterations*))
+(defparameter *timer-overhead-iterations*
+  500000)
 
 ;;; a dummy function that we profile to find profiling overhead
 (declaim (notinline compute-overhead-aux))
@@ -508,14 +464,15 @@ a very-long-running Lisp process."
 
 ;;; Return a newly computed OVERHEAD object.
 (defun compute-overhead ()
+  (format *debug-io* "~&measuring PROFILE overhead..")
   (flet ((frob ()
           (let ((start (get-internal-ticks))
                 (fun (symbol-function 'compute-overhead-aux)))
-            (dotimes (i +timer-overhead-iterations+)
+            (dotimes (i *timer-overhead-iterations*)
               (funcall fun fun))
             (/ (float (- (get-internal-ticks) start))
                (float +ticks-per-second+)
-               (float +timer-overhead-iterations+)))))
+               (float *timer-overhead-iterations*)))))
     (let (;; Measure unprofiled calls to estimate call overhead.
          (call-overhead (frob))
          total-overhead
@@ -533,14 +490,16 @@ a very-long-running Lisp process."
          (setf internal-overhead
                (/ (float time)
                   (float +ticks-per-second+)
-                  (float +timer-overhead-iterations+))))
+                  (float *timer-overhead-iterations*))))
        (unprofile compute-overhead-aux))
-      (make-overhead :call call-overhead
-                    :total total-overhead
-                    :internal internal-overhead))))
+      (prog1
+         (make-overhead :call call-overhead
+                        :total total-overhead
+                        :internal internal-overhead)
+       (format *debug-io* "done~%")))))
 
 ;;; It would be bad to compute *OVERHEAD*, save it into a .core file,
-;;; then load old *OVERHEAD* value from the .core file into a
+;;; then load the old *OVERHEAD* value from the .core file into a
 ;;; different machine running at a different speed. We avoid this by
 ;;; erasing *CALL-OVERHEAD* whenever we save a .core file.
 (pushnew (lambda ()