1 ;;;; a tracing facility
3 ;;;; This software is part of the SBCL system. See the README file for
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.
12 (in-package "SB-DEBUG") ; (SB-, not SB!, since we're built in warm load.)
14 ;;; FIXME: Why, oh why, doesn't the SB-DEBUG package use the SB-DI
15 ;;; package? That would let us get rid of a whole lot of stupid
18 (defvar *trace-values
* nil
20 "This is bound to the returned values when evaluating :BREAK-AFTER and
23 (defvar *trace-indentation-step
* 2
25 "the increase in trace indentation at each call level")
27 (defvar *max-trace-indentation
* 40
29 "If the trace indentation exceeds this value, then indentation restarts at
32 (defvar *trace-encapsulate-default
* t
34 "the default value for the :ENCAPSULATE option to TRACE")
38 ;;; a hash table that maps each traced function to the TRACE-INFO. The
39 ;;; entry for a closure is the shared function entry object.
40 (defvar *traced-funs
* (make-hash-table :test
'eq
:synchronized t
))
42 ;;; A TRACE-INFO object represents all the information we need to
43 ;;; trace a given function.
44 (def!struct
(trace-info
45 (:make-load-form-fun sb-kernel
:just-dump-it-normally
)
46 (:print-object
(lambda (x stream
)
47 (print-unreadable-object (x stream
:type t
)
48 (prin1 (trace-info-what x
) stream
)))))
49 ;; the original representation of the thing traced
50 (what nil
:type
(or function cons symbol
))
51 ;; Is WHAT a function name whose definition we should track?
53 ;; Is tracing to be done by encapsulation rather than breakpoints?
55 (encapsulated *trace-encapsulate-default
*)
56 ;; Has this trace been untraced?
58 ;; breakpoints we set up to trigger tracing
59 (start-breakpoint nil
:type
(or sb-di
:breakpoint null
))
60 (end-breakpoint nil
:type
(or sb-di
:breakpoint null
))
61 ;; the list of function names for WHEREIN, or NIL if unspecified
62 (wherein nil
:type list
)
63 ;; should we trace methods given a generic function to trace?
66 ;; The following slots represent the forms that we are supposed to
67 ;; evaluate on each iteration. Each form is represented by a cons
68 ;; (Form . Function), where the Function is the cached result of
69 ;; coercing Form to a function. Forms which use the current
70 ;; environment are converted with PREPROCESS-FOR-EVAL, which gives
71 ;; us a one-arg function. Null environment forms also have one-arg
72 ;; functions, but the argument is ignored. NIL means unspecified
75 ;; current environment forms
78 ;; List of current environment forms
80 ;; null environment forms
83 ;; list of null environment forms
84 (print-after () :type list
))
86 ;;; This is a list of conses (fun-end-cookie . condition-satisfied),
87 ;;; which we use to note distinct dynamic entries into functions. When
88 ;;; we enter a traced function, we add a entry to this list holding
89 ;;; the new end-cookie and whether the trace condition was satisfied.
90 ;;; We must save the trace condition so that the after breakpoint
91 ;;; knows whether to print. The length of this list tells us the
92 ;;; indentation to use for printing TRACE messages.
94 ;;; This list also helps us synchronize the TRACE facility dynamically
95 ;;; for detecting non-local flow of control. Whenever execution hits a
96 ;;; :FUN-END breakpoint used for TRACE'ing, we look for the
97 ;;; FUN-END-COOKIE at the top of *TRACED-ENTRIES*. If it is not
98 ;;; there, we discard any entries that come before our cookie.
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
*))
106 ;;; This variable is used to discourage infinite recursions when some
107 ;;; trace action invokes a function that is itself traced. In this
108 ;;; case, we quietly ignore the inner tracing.
109 (defvar *in-trace
* nil
)
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
115 ;;; a closure, we strip off the closure and return the bare code. The
116 ;;; second value is T if the argument was a function name. The third
117 ;;; value is one of :COMPILED, :COMPILED-CLOSURE, :INTERPRETED,
118 ;;; :INTERPRETED-CLOSURE and :FUNCALLABLE-INSTANCE.
119 (defun trace-fdefinition (x)
120 (multiple-value-bind (res named-p
)
123 (cond ((special-operator-p x
)
124 (error "can't trace special form ~S" x
))
127 (values (fdefinition x
) t
))))
129 (t (values (fdefinition x
) t
)))
130 (case (sb-kernel:widetag-of res
)
131 (#.sb-vm
:closure-header-widetag
132 (values (sb-kernel:%closure-fun res
)
135 (#.sb-vm
:funcallable-instance-header-widetag
136 (values res named-p
:funcallable-instance
))
137 (t (values res named-p
:compiled
)))))
139 ;;; When a function name is redefined, and we were tracing that name,
140 ;;; then untrace the old definition and trace the new one.
141 (defun trace-redefined-update (fname new-value
)
142 (when (fboundp fname
)
143 (let* ((fun (trace-fdefinition fname
))
144 (info (gethash fun
*traced-funs
*)))
145 (when (and info
(trace-info-named info
))
147 (trace-1 fname info new-value
)))))
148 (push #'trace-redefined-update
*setf-fdefinition-hook
*)
150 ;;; Annotate a FORM to evaluate with pre-converted functions. FORM is
151 ;;; really a cons (EXP . FUNCTION). LOC is the code location to use
152 ;;; for the lexical environment. If LOC is NIL, evaluate in the null
153 ;;; environment. If FORM is NIL, just return NIL.
154 (defun coerce-form (form loc
)
156 (let ((exp (car form
)))
157 (if (sb-di:code-location-p loc
)
158 (let ((fun (sb-di:preprocess-for-eval exp loc
)))
159 (declare (type function fun
))
162 (let ((*current-frame
* frame
))
163 (funcall fun frame
)))))
164 (let* ((bod (ecase loc
167 `(locally (declare (disable-package-locks sb-debug
:arg arg-list
))
168 (flet ((sb-debug:arg
(n)
169 (declare (special arg-list
))
171 (declare (ignorable #'sb-debug
:arg
)
172 (enable-package-locks sb-debug
:arg arg-list
))
174 (fun (coerce `(lambda () ,bod
) 'function
)))
177 (declare (ignore frame
))
178 (let ((*current-frame
* nil
))
179 (funcall fun
)))))))))
181 (defun coerce-form-list (forms loc
)
182 (mapcar (lambda (x) (coerce-form x loc
)) forms
))
184 ;;; Print indentation according to the number of trace entries.
185 ;;; Entries whose condition was false don't count.
186 (defun print-trace-indentation ()
188 (dolist (entry *traced-entries
*)
189 (when (cdr entry
) (incf depth
)))
192 (+ (mod (* depth
*trace-indentation-step
*)
193 (- *max-trace-indentation
* *trace-indentation-step
*))
194 *trace-indentation-step
*)
197 ;;; Return true if any of the NAMES appears on the stack below FRAME.
198 (defun trace-wherein-p (frame names
)
199 (do ((frame (sb-di:frame-down frame
) (sb-di:frame-down frame
)))
201 (when (member (sb-di:debug-fun-name
(sb-di:frame-debug-fun frame
))
206 ;;; Handle PRINT and PRINT-AFTER options.
207 (defun trace-print (frame forms
)
210 (print-trace-indentation)
211 (format t
"~@<~S ~_= ~S~:>" (car ele
) (funcall (cdr ele
) frame
))
214 ;;; Test a BREAK option, and if true, break.
215 (defun trace-maybe-break (info break where frame
)
216 (when (and break
(funcall (cdr break
) frame
))
217 (sb-di:flush-frames-above frame
)
218 (let ((*stack-top-hint
* frame
))
219 (break "breaking ~A traced call to ~S:"
221 (trace-info-what info
)))))
223 ;;; Discard any invalid cookies on our simulated stack. Encapsulated
224 ;;; entries are always valid, since we bind *TRACED-ENTRIES* in the
226 (defun discard-invalid-entries (frame)
228 (when (or (null *traced-entries
*)
229 (let ((cookie (caar *traced-entries
*)))
231 (sb-di:fun-end-cookie-valid-p frame cookie
))))
233 (pop *traced-entries
*)))
237 ;;; Return a closure that can be used for a function start breakpoint
238 ;;; hook function and a closure that can be used as the FUN-END-COOKIE
239 ;;; function. The first communicates the sense of the
240 ;;; TRACE-INFO-CONDITION to the second via a closure variable.
241 (defun trace-start-breakpoint-fun (info)
246 (declare (ignore bpt
))
247 (discard-invalid-entries frame
)
248 (let ((condition (trace-info-condition info
))
249 (wherein (trace-info-wherein info
)))
251 (and (not *in-trace
*)
253 (funcall (cdr condition
) frame
))
255 (trace-wherein-p frame wherein
)))))
257 (let ((sb-kernel:*current-level-in-print
* 0)
258 (*standard-output
* (make-string-output-stream))
261 (print-trace-indentation)
262 (if (trace-info-encapsulated info
)
263 ;; FIXME: These special variables should be given
264 ;; *FOO*-style names, and probably declared globally
267 (declare (special basic-definition arg-list
))
268 (prin1 `(,(trace-info-what info
)
269 ,@(mapcar #'ensure-printable-object arg-list
))))
270 (print-frame-call frame
*standard-output
*))
272 (trace-print frame
(trace-info-print info
))
273 (write-sequence (get-output-stream-string *standard-output
*)
275 (finish-output *trace-output
*))
276 (trace-maybe-break info
(trace-info-break info
) "before" frame
)))
278 (lambda (frame cookie
)
279 (declare (ignore frame
))
280 (push (cons cookie conditionp
) *traced-entries
*)))))
282 ;;; This prints a representation of the return values delivered.
283 ;;; First, this checks to see that cookie is at the top of
284 ;;; *TRACED-ENTRIES*; if it is not, then we need to adjust this list
285 ;;; to determine the correct indentation for output. We then check to
286 ;;; see whether the function is still traced and that the condition
287 ;;; succeeded before printing anything.
288 (declaim (ftype (function (trace-info) function
) trace-end-breakpoint-fun
))
289 (defun trace-end-breakpoint-fun (info)
290 (lambda (frame bpt
*trace-values
* cookie
)
291 (declare (ignore bpt
))
292 (unless (eq cookie
(caar *traced-entries
*))
293 (setf *traced-entries
*
294 (member cookie
*traced-entries
* :key
#'car
)))
296 (let ((entry (pop *traced-entries
*)))
297 (when (and (not (trace-info-untraced info
))
299 (let ((cond (trace-info-condition-after info
)))
300 (and cond
(funcall (cdr cond
) frame
)))))
301 (let ((sb-kernel:*current-level-in-print
* 0)
302 (*standard-output
* (make-string-output-stream))
305 (let ((*print-pretty
* t
))
306 (pprint-logical-block (*standard-output
* nil
)
307 (print-trace-indentation)
308 (pprint-indent :current
2)
309 (format t
"~S returned" (trace-info-what info
))
310 (dolist (v *trace-values
*)
312 (pprint-newline :linear
)
313 (prin1 (ensure-printable-object v
))))
315 (trace-print frame
(trace-info-print-after info
))
316 (write-sequence (get-output-stream-string *standard-output
*)
318 (finish-output *trace-output
*))
319 (trace-maybe-break info
320 (trace-info-break-after info
)
324 ;;; This function is called by the trace encapsulation. It calls the
325 ;;; breakpoint hook functions with NIL for the breakpoint and cookie,
326 ;;; which we have cleverly contrived to work for our hook functions.
327 (defun trace-call (info)
328 (multiple-value-bind (start cookie
) (trace-start-breakpoint-fun info
)
329 (declare (type function start cookie
))
330 (let ((frame (sb-di:frame-down
(sb-di:top-frame
))))
331 (funcall start frame nil
)
332 (let ((*traced-entries
* *traced-entries
*))
333 (declare (special basic-definition arg-list
))
334 (funcall cookie frame nil
)
337 (apply basic-definition arg-list
))))
338 (funcall (trace-end-breakpoint-fun info
) frame nil vals nil
)
339 (values-list vals
))))))
341 ;;; Trace one function according to the specified options. We copy the
342 ;;; trace info (it was a quoted constant), fill in the functions, and
343 ;;; then install the breakpoints or encapsulation.
345 ;;; If non-null, DEFINITION is the new definition of a function that
346 ;;; we are automatically retracing.
347 (defun trace-1 (function-or-name info
&optional definition
)
348 (multiple-value-bind (fun named kind
)
351 (nth-value 2 (trace-fdefinition definition
)))
352 (trace-fdefinition function-or-name
))
353 (when (gethash fun
*traced-funs
*)
354 (warn "~S is already TRACE'd, untracing it first." function-or-name
)
357 (let* ((debug-fun (sb-di:fun-debug-fun fun
))
359 (if (eq (trace-info-encapsulated info
) :default
)
363 (unless (functionp function-or-name
)
364 (warn "tracing shared code for ~S:~% ~S"
368 ((:interpreted
:interpreted-closure
:funcallable-instance
)
370 (trace-info-encapsulated info
)))
371 (loc (if encapsulated
373 (sb-di:debug-fun-start-location debug-fun
)))
374 (info (make-trace-info
375 :what function-or-name
377 :encapsulated encapsulated
378 :wherein
(trace-info-wherein info
)
379 :methods
(trace-info-methods info
)
380 :condition
(coerce-form (trace-info-condition info
) loc
)
381 :break
(coerce-form (trace-info-break info
) loc
)
382 :print
(coerce-form-list (trace-info-print info
) loc
)
383 :break-after
(coerce-form (trace-info-break-after info
) nil
)
385 (coerce-form (trace-info-condition-after info
) nil
)
387 (coerce-form-list (trace-info-print-after info
) nil
))))
389 (dolist (wherein (trace-info-wherein info
))
390 (unless (or (stringp wherein
)
392 (warn ":WHEREIN name ~S is not a defined global function."
398 (error "can't use encapsulation to trace anonymous function ~S"
400 (encapsulate function-or-name
'trace
`(trace-call ',info
)))
402 (multiple-value-bind (start-fun cookie-fun
)
403 (trace-start-breakpoint-fun info
)
404 (let ((start (sb-di:make-breakpoint start-fun debug-fun
406 (end (sb-di:make-breakpoint
407 (trace-end-breakpoint-fun info
)
408 debug-fun
:kind
:fun-end
409 :fun-end-cookie cookie-fun
)))
410 (setf (trace-info-start-breakpoint info
) start
)
411 (setf (trace-info-end-breakpoint info
) end
)
412 ;; The next two forms must be in the order in which they
413 ;; appear, since the start breakpoint must run before the
414 ;; fun-end breakpoint's start helper (which calls the
415 ;; cookie function.) One reason is that cookie function
416 ;; requires that the CONDITIONP shared closure variable be
418 (sb-di:activate-breakpoint start
)
419 (sb-di:activate-breakpoint end
)))))
421 (setf (gethash fun
*traced-funs
*) info
))
423 (when (and (typep fun
'generic-function
)
424 (trace-info-methods info
)
425 ;; we are going to trace the method functions directly.
426 (not (trace-info-encapsulated info
)))
427 (dolist (method (sb-mop:generic-function-methods fun
))
428 (let ((mf (sb-mop:method-function method
)))
429 ;; NOTE: this direct style of tracing methods -- tracing the
430 ;; pcl-internal method functions -- is only one possible
431 ;; alternative. It fails (a) when encapulation is
432 ;; requested, because the function objects themselves are
433 ;; stored in the method object; (b) when the method in
434 ;; question is particularly simple, when the method
435 ;; functionality is in the dfun. See src/pcl/env.lisp for a
436 ;; stub implementation of encapsulating through a
437 ;; traced-method class.
439 (when (typep mf
'sb-pcl
::%method-function
)
440 (trace-1 (sb-pcl::%method-function-fast-function mf
) info
))))))
446 ;;; Parse leading trace options off of SPECS, modifying INFO
447 ;;; accordingly. The remaining portion of the list is returned when we
448 ;;; encounter a plausible function name.
449 (defun parse-trace-options (specs info
)
450 (let ((current specs
))
452 (when (endp current
) (return))
453 (let ((option (first current
))
454 (value (cons (second current
) nil
)))
456 (:report
(error "stub: The :REPORT option is not yet implemented."))
457 (:condition
(setf (trace-info-condition info
) value
))
459 (setf (trace-info-condition info
) (cons nil nil
))
460 (setf (trace-info-condition-after info
) value
))
462 (setf (trace-info-condition info
) value
)
463 (setf (trace-info-condition-after info
) value
))
465 (setf (trace-info-wherein info
)
466 (if (listp (car value
)) (car value
) value
)))
468 (setf (trace-info-encapsulated info
) (car value
)))
470 (setf (trace-info-methods info
) (car value
)))
471 (:break
(setf (trace-info-break info
) value
))
472 (:break-after
(setf (trace-info-break-after info
) value
))
474 (setf (trace-info-break info
) value
)
475 (setf (trace-info-break-after info
) value
))
477 (setf (trace-info-print info
)
478 (append (trace-info-print info
) (list value
))))
480 (setf (trace-info-print-after info
)
481 (append (trace-info-print-after info
) (list value
))))
483 (setf (trace-info-print info
)
484 (append (trace-info-print info
) (list value
)))
485 (setf (trace-info-print-after info
)
486 (append (trace-info-print-after info
) (list value
))))
490 (error "missing argument to ~S TRACE option" option
))
494 ;;; Compute the expansion of TRACE in the non-trivial case (arguments
496 (defun expand-trace (specs)
499 (let* ((global-options (make-trace-info))
500 (current (parse-trace-options specs global-options
)))
502 (when (endp current
) (return))
503 (let ((name (pop current
))
504 (options (copy-trace-info global-options
)))
507 (let ((temp (gensym)))
508 (binds `(,temp
,(pop current
)))
509 (forms `(trace-1 ,temp
',options
))))
510 ((and (keywordp name
)
511 (not (or (fboundp name
) (macro-function name
))))
512 (error "unknown TRACE option: ~S" name
))
514 (let ((package (find-undeleted-package-or-lose name
)))
515 (do-all-symbols (symbol (find-package name
))
516 (when (eql package
(symbol-package symbol
))
517 (when (and (fboundp symbol
)
518 (not (macro-function symbol
))
519 (not (special-operator-p symbol
)))
520 (forms `(trace-1 ',symbol
',options
)))
521 (let ((setf-name `(setf ,symbol
)))
522 (when (fboundp setf-name
)
523 (forms `(trace-1 ',setf-name
',options
))))))))
524 ;; special-case METHOD: it itself is not a general function
525 ;; name symbol, but it (at least here) designates one of a
527 ((and (consp name
) (eq (car name
) 'method
))
528 (when (fboundp (list* 'sb-pcl
::slow-method
(cdr name
)))
529 (forms `(trace-1 ',(list* 'sb-pcl
::slow-method
(cdr name
))
531 (when (fboundp (list* 'sb-pcl
::fast-method
(cdr name
)))
532 (forms `(trace-1 ',(list* 'sb-pcl
::fast-method
(cdr name
))
535 (forms `(trace-1 ',name
',options
))))
536 (setq current
(parse-trace-options current options
)))))
541 (defun %list-traced-funs
()
542 (loop for x being each hash-value in
*traced-funs
*
543 collect
(trace-info-what x
)))
545 (defmacro trace
(&rest specs
)
547 "TRACE {Option Global-Value}* {Name {Option Value}*}*
549 TRACE is a debugging tool that provides information when specified
550 functions are called. In its simplest form:
552 (TRACE NAME-1 NAME-2 ...)
554 The NAMEs are not evaluated. Each may be a symbol, denoting an
555 individual function, or a string, denoting all functions fbound to
556 symbols whose home package is the package with the given name.
558 Options allow modification of the default behavior. Each option is a
559 pair of an option keyword and a value form. Global options are
560 specified before the first name, and affect all functions traced by a
561 given use of TRACE. Options may also be interspersed with function
562 names, in which case they act as local options, only affecting tracing
563 of the immediately preceding function name. Local options override
566 By default, TRACE causes a printout on *TRACE-OUTPUT* each time that
567 one of the named functions is entered or returns. (This is the basic,
568 ANSI Common Lisp behavior of TRACE.) As an SBCL extension, the
569 :REPORT SB-EXT:PROFILE option can be used to instead cause information
570 to be silently recorded to be inspected later using the SB-EXT:PROFILE
573 The following options are defined:
576 If Report-Type is TRACE (the default) then information is reported
577 by printing immediately. If Report-Type is SB-EXT:PROFILE, information
578 is recorded for later summary by calls to SB-EXT:PROFILE. If
579 Report-Type is NIL, then the only effect of the trace is to execute
580 other options (e.g. PRINT or BREAK).
583 :CONDITION-AFTER Form
585 If :CONDITION is specified, then TRACE does nothing unless Form
586 evaluates to true at the time of the call. :CONDITION-AFTER is
587 similar, but suppresses the initial printout, and is tested when the
588 function returns. :CONDITION-ALL tries both before and after.
589 This option is not supported with :REPORT PROFILE.
594 If specified, and Form evaluates to true, then the debugger is invoked
595 at the start of the function, at the end of the function, or both,
596 according to the respective option.
601 In addition to the usual printout, the result of evaluating Form is
602 printed at the start of the function, at the end of the function, or
603 both, according to the respective option. Multiple print options cause
604 multiple values to be printed.
607 If specified, Names is a function name or list of names. TRACE does
608 nothing unless a call to one of those functions encloses the call to
609 this function (i.e. it would appear in a backtrace.) Anonymous
610 functions have string names like \"DEFUN FOO\". This option is not
611 supported with :REPORT PROFILE.
613 :ENCAPSULATE {:DEFAULT | T | NIL}
614 If T, the tracing is done via encapsulation (redefining the function
615 name) rather than by modifying the function. :DEFAULT is the default,
616 and means to use encapsulation for interpreted functions and funcallable
617 instances, breakpoints otherwise. When encapsulation is used, forms are
618 *not* evaluated in the function's lexical environment, but SB-DEBUG:ARG
622 If T, any function argument naming a generic function will have its
623 methods traced in addition to the generic function itself.
625 :FUNCTION Function-Form
626 This is a not really an option, but rather another way of specifying
627 what function to trace. The Function-Form is evaluated immediately,
628 and the resulting function is instrumented, i.e. traced or profiled
629 as specified in REPORT.
631 :CONDITION, :BREAK and :PRINT forms are evaluated in a context which
632 mocks up the lexical environment of the called function, so that
633 SB-DEBUG:VAR and SB-DEBUG:ARG can be used. The -AFTER and -ALL forms
634 are evaluated in the null environment."
637 '(%list-traced-funs
)))
641 ;;; Untrace one function.
642 (defun untrace-1 (function-or-name)
643 (let* ((fun (trace-fdefinition function-or-name
))
644 (info (gethash fun
*traced-funs
*)))
647 (warn "Function is not TRACEd: ~S" function-or-name
))
650 ((trace-info-encapsulated info
)
651 (unencapsulate (trace-info-what info
) 'trace
))
653 (sb-di:delete-breakpoint
(trace-info-start-breakpoint info
))
654 (sb-di:delete-breakpoint
(trace-info-end-breakpoint info
))))
655 (setf (trace-info-untraced info
) t
)
656 (remhash fun
*traced-funs
*)))))
658 ;;; Untrace all traced functions.
659 (defun untrace-all ()
660 (dolist (fun (%list-traced-funs
))
664 (defun untrace-package (name)
665 (let ((package (find-package name
)))
667 (dolist (fun (%list-traced-funs
))
668 (cond ((and (symbolp fun
) (eq package
(symbol-package fun
)))
670 ((and (consp fun
) (eq 'setf
(car fun
))
671 (symbolp (second fun
))
672 (eq package
(symbol-package (second fun
))))
673 (untrace-1 fun
)))))))
675 (defmacro untrace
(&rest specs
)
677 "Remove tracing from the specified functions. Untraces all
678 functions when called with no arguments."
682 for name
= (pop specs
)
683 collect
(cond ((eq name
:function
)
684 `(untrace-1 ,(pop specs
)))
686 `(untrace-package ,name
))
688 `(untrace-1 ',name
))))