5.21.4.2 Profiling or Tracing a Procedure's Code

What if you wanted to get a trace of everything that the Guile evaluator does within a given procedure, but without Guile stopping and waiting for your input at every step? For this requirement you can install a trap on the procedure, as in the previous example, but instead of debug-trap or gds-debug-trap, use the trace-trap and trace-until-exit behaviours provided by the (ice-9 debugging trace) module.

     guile> (use-modules (ice-9 debugging traps) (ice-9 debugging trace))
     guile> (load "matrix.scm")
     guile> (install-trap (make <procedure-trap>
                            #:procedure mkmatrix
                            #:behaviour (list trace-trap trace-until-exit)))
     guile> (do-main 4)
     |  2: [mkmatrix]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> define #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> define #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq define (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> define #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> define #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq define (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  2: (letrec ((yy 23)) (let ((x 1)) (quote this-is-a-matric)))
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  2: (let ((x 1)) (quote this-is-a-matric))
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  3: [#<procedure #f (a sym definep)> #<autoload # b7c93870> let #f]
     |  4: (and (memq sym bindings) (let ...))
     |  5: (memq sym bindings)
     |  5: [memq let (debug)]
     |  5: =>#f
     |  2: [let (let # #) (# # #)]
     |  2: [let (let # #) (# # #)]
     |  2: =>(#@let* (x 1) #@let (quote this-is-a-matric))
     this-is-a-matric
     guile> (do-main 4)
     |  2: [mkmatrix]
     |  2: (letrec ((yy 23)) (let* ((x 1)) (quote this-is-a-matric)))
     |  2: (let* ((x 1)) (quote this-is-a-matric))
     |  2: (quote this-is-a-matric)
     |  2: =>this-is-a-matric
     this-is-a-matric
     guile>

This example shows the default configuration for how each line of trace output is formatted, which is:

• the character |, a visual clue that the line is a line of trace output, followed by
• a number indicating the real evaluator stack depth (where “real” means not counting tail-calls), followed by
• a summary of the expression being evaluated ((...)), the procedure being called ([...]), or the value being returned from an evaluation or procedure call (=>...).

You can customize (ice-9 debugging trace) to show different information in each trace line using the set-trace-layout procedure. The next example shows how to get the source location in each trace line instead of the stack depth.

     guile> (set-trace-layout "|~16@a: ~a\n" trace/source trace/info)
     guile> (do-main 4)
     |  matrix.scm:7:2: [mkmatrix]
     |                : (letrec ((yy 23)) (let* ((x 1)) (quote this-is-a-matric)))
     |  matrix.scm:3:2: (let* ((x 1)) (quote this-is-a-matric))
     |  matrix.scm:4:4: (quote this-is-a-matric)
     |  matrix.scm:4:4: =>this-is-a-matric
     this-is-a-matric
     guile>

(For anyone wondering why the first (do-main 4) call above generates lots more trace lines than the subsequent calls: these examples also demonstrate how the Guile evaluator “memoizes” code. When Guile evaluates a source code expression for the first time, it changes some parts of the expression so that they will be quicker to evaluate when that expression is evaluated again; this is called memoization. The trace output from the first (do-main 4) call shows memoization steps, such as an internal define being transformed to a letrec.)