Tracing Procedures in MIT-Scheme

You are probably very familiar with inserting print statements throughout your code in order to track down the source of a bug. Such print statements often indicate when a particular function is being called, along with its parameters, or when a particular function returns, along with its return values. While such print statements can greatly aid debugging, adding such print statements to a program is a tedious and error prone process.

MIT-Scheme has a wonderful procedure tracing facility that greatly simplifies debugging by making it unnecessary to insert such "print" statements in most situations. Instead, all one needs to do to get the effect of adding such "print" statements is to "trace" the procedure. This is done by evaluating the expression (trace proc), where proc is an expression that denotes the function for which you want information printed on every entry and exit to that function.

Here is a simple example of tracing. Consider the following summation procedure:

 
(define sum
  (lambda (lst)
    (if (null? lst)
        0
        (+ (car lst)
           (sum (cdr lst))))))

We can trace the execution of this procedure by evaluating the following expression:

(trace sum)

If we now evaluate (sum '(1 2 3 4)), Scheme prints out the following information. Note how the name of traced procedure and its arguments are printed whenever the procedure is invoked, and its name, arguments, and return value are printed whenever it returns.

(sum '(1 2 3 4))
[Entering #[compound-procedure 1 sum]
    Args: (1 2 3 4)]
[Entering #[compound-procedure 1 sum]
    Args: (2 3 4)]
[Entering #[compound-procedure 1 sum]
    Args: (3 4)]
[Entering #[compound-procedure 1 sum]
    Args: (4)]
[Entering #[compound-procedure 1 sum]
    Args: ()]
[0
      <== #[compound-procedure 1 sum]
    Args: ()]
[4
      <== #[compound-procedure 1 sum]
    Args: (4)]
[7
      <== #[compound-procedure 1 sum]
    Args: (3 4)]
[9
      <== #[compound-procedure 1 sum]
    Args: (2 3 4)]
[10
      <== #[compound-procedure 1 sum]
    Args: (1 2 3 4)]
;Value: 10

You can trace as many procedures as you want to at one time. For instance, consider the following two procedures that implement insertion sort:

(define insertion-sort
  (lambda (lst)
    (if (null? lst)
        '()
        (insert (car lst)
                (insertion-sort (cdr lst))))))
 
(define insert
  (lambda (elt sorted-lst)
    (if (null? sorted-lst)
        (list elt)
        (if (<= elt (car sorted-lst))
            (cons elt sorted-lst)
            (cons (car sorted-lst)
                  (insert elt (cdr sorted-lst)))))))

We can trace both such procedures via the following:

(trace insertion-sort)
(trace insert)

Here is an example of a sample trace. Study it carefully to make sure you understand how insertion sort is working.

(insertion-sort '(3 5 1 4 2))
[Entering #[compound-procedure 2 insertion-sort]
    Args: (3 5 1 4 2)]
[Entering #[compound-procedure 2 insertion-sort]
    Args: (5 1 4 2)]
[Entering #[compound-procedure 2 insertion-sort]
    Args: (1 4 2)]
[Entering #[compound-procedure 2 insertion-sort]
    Args: (4 2)]
[Entering #[compound-procedure 2 insertion-sort]
    Args: (2)]
[Entering #[compound-procedure 2 insertion-sort]
    Args: ()]
[()
      <== #[compound-procedure 2 insertion-sort]
    Args: ()]
[Entering #[compound-procedure 4 insert]
    Args: 2
          ()]
[(2)
      <== #[compound-procedure 4 insert]
    Args: 2
          ()]
[(2)
      <== #[compound-procedure 2 insertion-sort]
    Args: (2)]
[Entering #[compound-procedure 4 insert]
    Args: 4
          (2)]
[Entering #[compound-procedure 4 insert]
    Args: 4
          ()]
[(4)
      <== #[compound-procedure 4 insert]
    Args: 4
          ()]
[(2 4)
      <== #[compound-procedure 4 insert]
    Args: 4
          (2)]
[(2 4)
      <== #[compound-procedure 2 insertion-sort]
    Args: (4 2)]
[Entering #[compound-procedure 4 insert]
    Args: 1
          (2 4)]
[(1 2 4)
      <== #[compound-procedure 4 insert]
    Args: 1
          (2 4)]
[(1 2 4)
      <== #[compound-procedure 2 insertion-sort]
    Args: (1 4 2)]
[Entering #[compound-procedure 4 insert]
    Args: 5
          (1 2 4)]
[Entering #[compound-procedure 4 insert]
    Args: 5
          (2 4)]
    Args: 5
          (4)]
[Entering #[compound-procedure 4 insert]
    Args: 5
          ()]
[(5)
      <== #[compound-procedure 4 insert]
    Args: 5
          ()]
[(4 5)
      <== #[compound-procedure 4 insert]
    Args: 5
          (4)]
[(2 4 5)
      <== #[compound-procedure 4 insert]
    Args: 5
          (2 4)]
[(1 2 4 5)
      <== #[compound-procedure 4 insert]
    Args: 5
          (1 2 4)]
[(1 2 4 5)
      <== #[compound-procedure 2 insertion-sort]
    Args: (5 1 4 2)]
[Entering #[compound-procedure 4 insert]
    Args: 3
          (1 2 4 5)]
[Entering #[compound-procedure 4 insert]
    Args: 3
          (2 4 5)]
Buffers Files Tools Edit Search Help
[Entering #[compound-procedure 4 insert]
    Args: 3
          (4 5)]
[(3 4 5)
      <== #[compound-procedure 4 insert]
    Args: 3
          (4 5)]
[(2 3 4 5)
      <== #[compound-procedure 4 insert]
    Args: 3
          (2 4 5)]
[(1 2 3 4 5)
      <== #[compound-procedure 4 insert]
    Args: 3
          (1 2 4 5)]
[(1 2 3 4 5)
      <== #[compound-procedure 2 insertion-sort]
    Args: (3 5 1 4 2)]
;Value 5: (1 2 3 4 5)

A few more notes on tracing:

To stop tracing a procedure, you evaluate (untrace proc) , where proc is an expression denoting the procedure you no longer want to trace. Evaluating (untrace) will untrace all currently traced procedures.
If you define a new version of a function, any tracing for the previous version of the function will no longer be active. You will need to trace the new version of the function.
Tracing is an excellent way to localize bugs in your program. But it is also a good way to gain a better understanding for correct code. For instance, if you don't understand how a particular procedure definition works, trace it and try it out on some example inputs.