Initial revision
[sbcl.git] / src / code / ntrace.lisp
1 ;;;; a tracing facility based on breakpoints
2
3 ;;;; This software is part of the SBCL system. See the README file for
4 ;;;; more information.
5 ;;;;
6 ;;;; This software is derived from the CMU CL system, which was
7 ;;;; written at Carnegie Mellon University and released into the
8 ;;;; public domain. The software is in the public domain and is
9 ;;;; provided with absolutely no warranty. See the COPYING and CREDITS
10 ;;;; files for more information.
11
12 (in-package "SB-DEBUG")
13
14 (file-comment
15   "$Header$")
16
17 ;;; FIXME: Why, oh why, doesn't the SB-DEBUG package use the SB-DI package?
18 ;;; That would let us get rid of a whole lot of stupid prefixes..
19
20 (defvar *trace-values* nil
21   #+sb-doc
22   "This is bound to the returned values when evaluating :BREAK-AFTER and
23    :PRINT-AFTER forms.")
24
25 (defvar *trace-indentation-step* 2
26   #+sb-doc
27   "the increase in trace indentation at each call level")
28
29 (defvar *max-trace-indentation* 40
30   #+sb-doc
31   "If the trace indentation exceeds this value, then indentation restarts at
32    0.")
33
34 (defvar *trace-encapsulate-default* :default
35   #+sb-doc
36   "the default value for the :ENCAPSULATE option to TRACE")
37 \f
38 ;;;; internal state
39
40 ;;; a hash table that maps each traced function to the TRACE-INFO. The entry
41 ;;; for a closure is the shared function-entry object.
42 (defvar *traced-functions* (make-hash-table :test 'eq))
43
44 ;;; A TRACE-INFO object represents all the information we need to trace a
45 ;;; given function.
46 (def!struct (trace-info
47              (:make-load-form-fun sb-kernel:just-dump-it-normally)
48              (:print-object (lambda (x stream)
49                               (print-unreadable-object (x stream :type t)
50                                 (prin1 (trace-info-what x) stream)))))
51   ;; the original representation of the thing traced
52   (what nil :type (or function cons symbol))
53   ;; Is WHAT a function name whose definition we should track?
54   (named nil)
55   ;; Is tracing to be done by encapsulation rather than breakpoints?
56   ;; T implies NAMED.
57   (encapsulated *trace-encapsulate-default*)
58   ;; Has this trace been untraced?
59   (untraced nil)
60   ;; breakpoints we set up to trigger tracing
61   (start-breakpoint nil :type (or sb-di:breakpoint null))
62   (end-breakpoint nil :type (or sb-di:breakpoint null))
63   ;; the list of function names for WHEREIN, or NIL if unspecified
64   (wherein nil :type list)
65
66   ;; The following slots represent the forms that we are supposed to evaluate
67   ;; on each iteration. Each form is represented by a cons (Form . Function),
68   ;; where the Function is the cached result of coercing Form to a function.
69   ;; Forms which use the current environment are converted with
70   ;; PREPROCESS-FOR-EVAL, which gives us a one-arg function.
71   ;; Null environment forms also have one-arg functions, but the argument is
72   ;; ignored. NIL means unspecified (the default.)
73
74   ;; current environment forms
75   (condition nil)
76   (break nil)
77   ;; List of current environment forms
78   (print () :type list)
79   ;; null environment forms
80   (condition-after nil)
81   (break-after nil)
82   ;; list of null environment forms
83   (print-after () :type list))
84
85 ;;; This is a list of conses (function-end-cookie .
86 ;;; condition-satisfied), which we use to note distinct dynamic
87 ;;; entries into functions. When we enter a traced function, we add a
88 ;;; entry to this list holding the new end-cookie and whether the
89 ;;; trace condition was satisfied. We must save the trace condition so
90 ;;; that the after breakpoint knows whether to print. The length of
91 ;;; this list tells us the indentation to use for printing TRACE
92 ;;; messages.
93 ;;;
94 ;;; This list also helps us synchronize the TRACE facility dynamically
95 ;;; for detecting non-local flow of control. Whenever execution hits a
96 ;;; :function-end breakpoint used for TRACE'ing, we look for the
97 ;;; function-end-cookie at the top of *traced-entries*. If it is not
98 ;;; there, we discard any entries that come before our cookie.
99 ;;;
100 ;;; When we trace using encapsulation, we bind this variable and add
101 ;;; (NIL . CONDITION-SATISFIED), so a NIL "cookie" marks an
102 ;;; encapsulated tracing.
103 (defvar *traced-entries* ())
104 (declaim (list *traced-entries*))
105
106 ;;; This variable is used to discourage infinite recursions when some trace
107 ;;; action invokes a function that is itself traced. In this case, we quietly
108 ;;; ignore the inner tracing.
109 (defvar *in-trace* nil)
110 \f
111 ;;;; utilities
112
113 ;;;    Given a function name, a function or a macro name, return the raw
114 ;;; definition and some information. "Raw"  means that if the result is a
115 ;;; closure, we strip off the closure and return the bare code. The second
116 ;;; value is T if the argument was a function name. The third value is one of
117 ;;; :COMPILED, :COMPILED-CLOSURE, :INTERPRETED, :INTERPRETED-CLOSURE and
118 ;;; :FUNCALLABLE-INSTANCE.
119 (defun trace-fdefinition (x)
120   (multiple-value-bind (res named-p)
121       (typecase x
122         (symbol
123          (cond ((special-operator-p x)
124                 (error "can't trace special form ~S" x))
125                ((macro-function x))
126                (t
127                 (values (fdefinition x) t))))
128         (function x)
129         (t (values (fdefinition x) t)))
130     (if (sb-eval:interpreted-function-p res)
131         (values res named-p (if (sb-eval:interpreted-function-closure res)
132                                 :interpreted-closure :interpreted))
133         (case (sb-kernel:get-type res)
134           (#.sb-vm:closure-header-type
135            (values (sb-kernel:%closure-function res)
136                    named-p
137                    :compiled-closure))
138           (#.sb-vm:funcallable-instance-header-type
139            (values res named-p :funcallable-instance))
140           (t (values res named-p :compiled))))))
141
142 ;;; When a function name is redefined, and we were tracing that name, then
143 ;;; untrace the old definition and trace the new one.
144 (defun trace-redefined-update (fname new-value)
145   (when (fboundp fname)
146     (let* ((fun (trace-fdefinition fname))
147            (info (gethash fun *traced-functions*)))
148       (when (and info (trace-info-named info))
149         (untrace-1 fname)
150         (trace-1 fname info new-value)))))
151 (push #'trace-redefined-update sb-int:*setf-fdefinition-hook*)
152
153 ;;; Annotate some forms to evaluate with pre-converted functions. Each form
154 ;;; is really a cons (exp . function). Loc is the code location to use for
155 ;;; the lexical environment. If Loc is NIL, evaluate in the null environment.
156 ;;; If Form is NIL, just return NIL.
157 (defun coerce-form (form loc)
158   (when form
159     (let ((exp (car form)))
160       (if (sb-di:code-location-p loc)
161           (let ((fun (sb-di:preprocess-for-eval exp loc)))
162             (cons exp
163                   #'(lambda (frame)
164                       (let ((*current-frame* frame))
165                         (funcall fun frame)))))
166           (let* ((bod (ecase loc
167                         ((nil) exp)
168                         (:encapsulated
169                          `(flet ((sb-debug:arg (n)
170                                    (declare (special argument-list))
171                                    (elt argument-list n)))
172                             (declare (ignorable #'sb-debug:arg))
173                             ,exp))))
174                  (fun (coerce `(lambda () ,bod) 'function)))
175             (cons exp
176                   #'(lambda (frame)
177                       (declare (ignore frame))
178                       (let ((*current-frame* nil))
179                         (funcall fun)))))))))
180 (defun coerce-form-list (forms loc)
181   (mapcar #'(lambda (x) (coerce-form x loc)) forms))
182
183 ;;; Print indentation according to the number of trace entries.
184 ;;; Entries whose condition was false don't count.
185 (defun print-trace-indentation ()
186   (let ((depth 0))
187     (dolist (entry *traced-entries*)
188       (when (cdr entry) (incf depth)))
189     (format t
190             "~@V,0T~D: "
191             (+ (mod (* depth *trace-indentation-step*)
192                     (- *max-trace-indentation* *trace-indentation-step*))
193                *trace-indentation-step*)
194             depth)))
195
196 ;;; Return true if one of the Names appears on the stack below Frame.
197 (defun trace-wherein-p (frame names)
198   (do ((frame (sb-di:frame-down frame) (sb-di:frame-down frame)))
199       ((not frame) nil)
200     (when (member (sb-di:debug-function-name (sb-di:frame-debug-function
201                                               frame))
202                   names
203                   :test #'equal)
204       (return t))))
205
206 ;;; Handle print and print-after options.
207 (defun trace-print (frame forms)
208   (dolist (ele forms)
209     (fresh-line)
210     (print-trace-indentation)
211     (format t "~S = ~S" (car ele) (funcall (cdr ele) frame))))
212
213 ;;; Test a break option, and break if true.
214 (defun trace-maybe-break (info break where frame)
215   (when (and break (funcall (cdr break) frame))
216     (sb-di:flush-frames-above frame)
217     (let ((*stack-top-hint* frame))
218       (break "breaking ~A traced call to ~S:"
219              where
220              (trace-info-what info)))))
221
222 ;;; This function discards any invalid cookies on our simulated stack.
223 ;;; Encapsulated entries are always valid, since we bind *traced-entries* in
224 ;;; the encapsulation.
225 (defun discard-invalid-entries (frame)
226   (loop
227     (when (or (null *traced-entries*)
228               (let ((cookie (caar *traced-entries*)))
229                 (or (not cookie)
230                     (sb-di:function-end-cookie-valid-p frame cookie))))
231       (return))
232     (pop *traced-entries*)))
233 \f
234 ;;;; hook functions
235
236 ;;; Return a closure that can be used for a function start breakpoint hook
237 ;;; function and a closure that can be used as the FUNCTION-END-COOKIE
238 ;;; function. The first communicates the sense of the Condition to the second
239 ;;; via a closure variable.
240 (defun trace-start-breakpoint-fun (info)
241   (let (conditionp)
242     (values
243      #'(lambda (frame bpt)
244          (declare (ignore bpt))
245          (discard-invalid-entries frame)
246          (let ((condition (trace-info-condition info))
247                (wherein (trace-info-wherein info)))
248            (setq conditionp
249                  (and (not *in-trace*)
250                       (or (not condition)
251                           (funcall (cdr condition) frame))
252                       (or (not wherein)
253                           (trace-wherein-p frame wherein)))))
254
255          (when conditionp
256            (let ((sb-kernel:*current-level* 0)
257                  (*standard-output* *trace-output*)
258                  (*in-trace* t))
259              (fresh-line)
260              (print-trace-indentation)
261              (if (trace-info-encapsulated info)
262                  (locally (declare (special basic-definition argument-list))
263                    (prin1 `(,(trace-info-what info) ,@argument-list)))
264                  (print-frame-call frame))
265              (terpri)
266              (trace-print frame (trace-info-print info)))
267            (trace-maybe-break info (trace-info-break info) "before" frame)))
268
269      #'(lambda (frame cookie)
270          (declare (ignore frame))
271          (push (cons cookie conditionp) *traced-entries*)))))
272
273 ;;; This prints a representation of the return values delivered.
274 ;;; First, this checks to see that cookie is at the top of
275 ;;; *traced-entries*; if it is not, then we need to adjust this list
276 ;;; to determine the correct indentation for output. We then check to
277 ;;; see whether the function is still traced and that the condition
278 ;;; succeeded before printing anything.
279 (defun trace-end-breakpoint-fun (info)
280   #'(lambda (frame bpt *trace-values* cookie)
281       (declare (ignore bpt))
282       (unless (eq cookie (caar *traced-entries*))
283         (setf *traced-entries*
284               (member cookie *traced-entries* :key #'car)))
285
286       (let ((entry (pop *traced-entries*)))
287         (when (and (not (trace-info-untraced info))
288                    (or (cdr entry)
289                        (let ((cond (trace-info-condition-after info)))
290                          (and cond (funcall (cdr cond) frame)))))
291           (let ((sb-kernel:*current-level* 0)
292                 (*standard-output* *trace-output*)
293                 (*in-trace* t))
294             (fresh-line)
295             (pprint-logical-block (*standard-output* nil)
296               (print-trace-indentation)
297               (pprint-indent :current 2)
298               (format t "~S returned" (trace-info-what info))
299               (dolist (v *trace-values*)
300                 (write-char #\space)
301                 (pprint-newline :linear)
302                 (prin1 v)))
303             (terpri)
304             (trace-print frame (trace-info-print-after info)))
305           (trace-maybe-break info
306                              (trace-info-break-after info)
307                              "after"
308                              frame)))))
309 \f
310 ;;; This function is called by the trace encapsulation. It calls the
311 ;;; breakpoint hook functions with NIL for the breakpoint and cookie, which
312 ;;; we have cleverly contrived to work for our hook functions.
313 (defun trace-call (info)
314   (multiple-value-bind (start cookie) (trace-start-breakpoint-fun info)
315     (let ((frame (sb-di:frame-down (sb-di:top-frame))))
316       (funcall start frame nil)
317       (let ((*traced-entries* *traced-entries*))
318         (declare (special basic-definition argument-list))
319         (funcall cookie frame nil)
320         (let ((vals
321                (multiple-value-list
322                 (apply basic-definition argument-list))))
323           (funcall (trace-end-breakpoint-fun info) frame nil vals nil)
324           (values-list vals))))))
325 \f
326 ;;; Trace one function according to the specified options. We copy the
327 ;;; trace info (it was a quoted constant), fill in the functions, and then
328 ;;; install the breakpoints or encapsulation.
329 ;;;
330 ;;; If non-null, Definition is the new definition of a function that we are
331 ;;; automatically retracing.
332 (defun trace-1 (function-or-name info &optional definition)
333   (multiple-value-bind (fun named kind)
334       (if definition
335           (values definition t
336                   (nth-value 2 (trace-fdefinition definition)))
337           (trace-fdefinition function-or-name))
338     (when (gethash fun *traced-functions*)
339       ;; FIXME: should be STYLE-WARNING
340       (warn "Function ~S is already TRACE'd, retracing it." function-or-name)
341       (untrace-1 fun))
342
343     (let* ((debug-fun (sb-di:function-debug-function fun))
344            (encapsulated
345             (if (eq (trace-info-encapsulated info) :default)
346                 (ecase kind
347                   (:compiled nil)
348                   (:compiled-closure
349                    (unless (functionp function-or-name)
350                      (warn "Tracing shared code for ~S:~%  ~S"
351                            function-or-name
352                            fun))
353                    nil)
354                   ((:interpreted :interpreted-closure :funcallable-instance)
355                    t))
356                 (trace-info-encapsulated info)))
357            (loc (if encapsulated
358                     :encapsulated
359                     (sb-di:debug-function-start-location debug-fun)))
360            (info (make-trace-info
361                   :what function-or-name
362                   :named named
363                   :encapsulated encapsulated
364                   :wherein (trace-info-wherein info)
365                   :condition (coerce-form (trace-info-condition info) loc)
366                   :break (coerce-form (trace-info-break info) loc)
367                   :print (coerce-form-list (trace-info-print info) loc)
368                   :break-after (coerce-form (trace-info-break-after info) nil)
369                   :condition-after
370                   (coerce-form (trace-info-condition-after info) nil)
371                   :print-after
372                   (coerce-form-list (trace-info-print-after info) nil))))
373
374       (dolist (wherein (trace-info-wherein info))
375         (unless (or (stringp wherein)
376                     (fboundp wherein))
377           (warn ":WHEREIN name ~S is not a defined global function."
378                 wherein)))
379
380       (cond
381        (encapsulated
382         (unless named
383           (error "can't use encapsulation to trace anonymous function ~S"
384                  fun))
385         (sb-int:encapsulate function-or-name 'trace `(trace-call ',info)))
386        (t
387         (multiple-value-bind (start-fun cookie-fun)
388             (trace-start-breakpoint-fun info)
389           (let ((start (sb-di:make-breakpoint start-fun debug-fun
390                                               :kind :function-start))
391                 (end (sb-di:make-breakpoint
392                       (trace-end-breakpoint-fun info)
393                       debug-fun :kind :function-end
394                       :function-end-cookie cookie-fun)))
395             (setf (trace-info-start-breakpoint info) start)
396             (setf (trace-info-end-breakpoint info) end)
397             ;; The next two forms must be in the order in which they appear,
398             ;; since the start breakpoint must run before the function-end
399             ;; breakpoint's start helper (which calls the cookie function.)
400             ;; One reason is that cookie function requires that the CONDITIONP
401             ;; shared closure variable be initialized.
402             (sb-di:activate-breakpoint start)
403             (sb-di:activate-breakpoint end)))))
404
405       (setf (gethash fun *traced-functions*) info)))
406
407   function-or-name)
408 \f
409 ;;;; the TRACE macro
410
411 ;;; Parse leading trace options off of SPECS, modifying INFO accordingly. The
412 ;;; remaining portion of the list is returned when we encounter a plausible
413 ;;; function name.
414 (defun parse-trace-options (specs info)
415   (let ((current specs))
416     (loop
417       (when (endp current) (return))
418       (let ((option (first current))
419             (value (cons (second current) nil)))
420         (case option
421           (:report (error "stub: The :REPORT option is not yet implemented."))
422           (:condition (setf (trace-info-condition info) value))
423           (:condition-after
424            (setf (trace-info-condition info) (cons nil nil))
425            (setf (trace-info-condition-after info) value))
426           (:condition-all
427            (setf (trace-info-condition info) value)
428            (setf (trace-info-condition-after info) value))
429           (:wherein
430            (setf (trace-info-wherein info)
431                  (if (listp (car value)) (car value) value)))
432           (:encapsulate
433            (setf (trace-info-encapsulated info) (car value)))
434           (:break (setf (trace-info-break info) value))
435           (:break-after (setf (trace-info-break-after info) value))
436           (:break-all
437            (setf (trace-info-break info) value)
438            (setf (trace-info-break-after info) value))
439           (:print
440            (setf (trace-info-print info)
441                  (append (trace-info-print info) (list value))))
442           (:print-after
443            (setf (trace-info-print-after info)
444                  (append (trace-info-print-after info) (list value))))
445           (:print-all
446            (setf (trace-info-print info)
447                  (append (trace-info-print info) (list value)))
448            (setf (trace-info-print-after info)
449                  (append (trace-info-print-after info) (list value))))
450           (t (return)))
451         (pop current)
452         (unless current
453           (error "missing argument to ~S TRACE option" option))
454         (pop current)))
455     current))
456
457 ;;; Compute the expansion of TRACE in the non-trivial case (arguments
458 ;;; specified.)  If there are no :FUNCTION specs, then don't use a LET. This
459 ;;; allows TRACE to be used without the full interpreter.
460 (defun expand-trace (specs)
461   (collect ((binds)
462             (forms))
463     (let* ((global-options (make-trace-info))
464            (current (parse-trace-options specs global-options)))
465       (loop
466         (when (endp current) (return))
467         (let ((name (pop current))
468               (options (copy-trace-info global-options)))
469           (cond
470            ((eq name :function)
471             (let ((temp (gensym)))
472               (binds `(,temp ,(pop current)))
473               (forms `(trace-1 ,temp ',options))))
474            ((and (keywordp name)
475                  (not (or (fboundp name) (macro-function name))))
476             (error "unknown TRACE option: ~S" name))
477            (t
478             (forms `(trace-1 ',name ',options))))
479           (setq current (parse-trace-options current options)))))
480
481     (if (binds)
482         `(let ,(binds) (list ,@(forms)))
483         `(list ,@(forms)))))
484
485 (defun %list-traced-functions ()
486   (loop for x being each hash-value in *traced-functions*
487         collect (trace-info-what x)))
488
489 (defmacro trace (&rest specs)
490   #+sb-doc
491   "TRACE {Option Global-Value}* {Name {Option Value}*}*
492    TRACE is a debugging tool that provides information when specified functions
493    are called. In its simplest form:
494        (trace Name-1 Name-2 ...)
495    (The Names are not evaluated.)
496
497    Options allow modification of the default behavior. Each option is a pair
498    of an option keyword and a value form. Global options are specified before
499    the first name, and affect all functions traced by a given use of TRACE.
500    Options may also be interspersed with function names, in which case they
501    act as local options, only affecting tracing of the immediately preceding
502    function name. Local options override global options.
503
504    By default, TRACE causes a printout on *TRACE-OUTPUT* each time that
505    one of the named functions is entered or returns. (This is the
506    basic, ANSI Common Lisp behavior of TRACE.) As an SBCL extension, the
507    :REPORT SB-EXT:PROFILE option can be used to instead cause information
508    to be silently recorded to be inspected later using the SB-EXT:PROFILE
509    function.
510
511    The following options are defined:
512
513    :REPORT Report-Type
514        If Report-Type is TRACE (the default) then information is reported
515        by printing immediately. If Report-Type is SB-EXT:PROFILE, information
516        is recorded for later summary by calls to SB-EXT:PROFILE. If
517        Report-Type is NIL, then the only effect of the trace is to execute
518        other options (e.g. PRINT or BREAK).
519
520    :CONDITION Form
521    :CONDITION-AFTER Form
522    :CONDITION-ALL Form
523        If :CONDITION is specified, then TRACE does nothing unless Form
524        evaluates to true at the time of the call. :CONDITION-AFTER is
525        similar, but suppresses the initial printout, and is tested when the
526        function returns. :CONDITION-ALL tries both before and after.
527
528    :BREAK Form
529    :BREAK-AFTER Form
530    :BREAK-ALL Form
531        If specified, and Form evaluates to true, then the debugger is invoked
532        at the start of the function, at the end of the function, or both,
533        according to the respective option. 
534
535    :PRINT Form
536    :PRINT-AFTER Form
537    :PRINT-ALL Form
538        In addition to the usual printout, the result of evaluating Form is
539        printed at the start of the function, at the end of the function, or
540        both, according to the respective option. Multiple print options cause
541        multiple values to be printed.
542
543    :WHEREIN Names
544        If specified, Names is a function name or list of names. TRACE does
545        nothing unless a call to one of those functions encloses the call to
546        this function (i.e. it would appear in a backtrace.)  Anonymous
547        functions have string names like \"DEFUN FOO\". 
548
549    :ENCAPSULATE {:DEFAULT | T | NIL}
550        If T, the tracing is done via encapsulation (redefining the function
551        name) rather than by modifying the function. :DEFAULT is the default,
552        and means to use encapsulation for interpreted functions and funcallable
553        instances, breakpoints otherwise. When encapsulation is used, forms are
554        *not* evaluated in the function's lexical environment, but SB-DEBUG:ARG
555        can still be used.
556
557    :FUNCTION Function-Form
558        This is a not really an option, but rather another way of specifying
559        what function to trace. The Function-Form is evaluated immediately,
560        and the resulting function is traced.
561
562    :CONDITION, :BREAK and :PRINT forms are evaluated in the lexical environment
563    of the called function; SB-DEBUG:VAR and SB-DEBUG:ARG can be used. The
564    -AFTER and -ALL forms are evaluated in the null environment."
565   (if specs
566       (expand-trace specs)
567       '(%list-traced-functions)))
568 \f
569 ;;;; untracing
570
571 ;;; Untrace one function.
572 (defun untrace-1 (function-or-name)
573   (let* ((fun (trace-fdefinition function-or-name))
574          (info (gethash fun *traced-functions*)))
575     (cond
576      ((not info)
577       (warn "Function is not TRACEd: ~S" function-or-name))
578      (t
579       (cond
580        ((trace-info-encapsulated info)
581         (sb-int:unencapsulate (trace-info-what info) 'trace))
582        (t
583         (sb-di:delete-breakpoint (trace-info-start-breakpoint info))
584         (sb-di:delete-breakpoint (trace-info-end-breakpoint info))))
585       (setf (trace-info-untraced info) t)
586       (remhash fun *traced-functions*)))))
587
588 ;;; Untrace all traced functions.
589 (defun untrace-all ()
590   (dolist (fun (%list-traced-functions))
591     (untrace-1 fun))
592   t)
593
594 (defmacro untrace (&rest specs)
595   #+sb-doc
596   "Remove tracing from the specified functions. With no args, untrace all
597    functions."
598   (if specs
599       (collect ((res))
600         (let ((current specs))
601           (loop
602             (unless current (return))
603             (let ((name (pop current)))
604               (res (if (eq name :function)
605                        `(untrace-1 ,(pop current))
606                        `(untrace-1 ',name)))))
607           `(progn ,@(res) t)))
608       '(untrace-all)))