Re: frames / stacks / source? was Re: coverage/profiling

[Neil Jerram]

Neil Jerram <address@hidden> writes:

> guile-debugging should be able to accumulate coverage of all source
> expressions - say in a particular file - but it might incur a big
> performance cost in so doing.  I'll try this out and let you know what
> I find.

For the record, here is how one can do code coverage using
guile-debugging.  I appreciate this may in practice be too slow for
complex programs, but it seems to work reasonably for small amounts of
code.

First we implement a basic code coverage trap:

  (use-modules (ice-9 debugging traps))

  (define covered-file-names '())

  (define coverage-hash (make-hash-table 31))

  (define (cover-entry trap-context)
    (let ((source-pos (frame->source-position (tc:frame trap-context))))
      (if (and source-pos
               (member (car source-pos) covered-file-names))
          (hash-set! coverage-hash
                     source-pos
                     (+ (or (hash-ref coverage-hash source-pos) 0) 1)))))

  (define coverage-trap (make <entry-trap> #:behaviour cover-entry))

Then here's an example of how to use this trap:

  (use-modules (ice-9 debugging example-fns))

  (set! covered-file-names
    '("/usr/share/guile/ice-9/debugging/example-fns.scm "))

  (install-trap coverage-trap)

  (fact2 5)

  (uninstall-trap coverage-trap) ;; The trap does hit performance a
  ;; bit while it is installed, so this uninstall is just to get back to
  ;; normal performance.

And here are the results that I get from this, which look correct to me:

  (hash-fold (lambda (key value acc)
               (format #t "~S: ~S\n" key value))
             #f
             coverage-hash)
  |=
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 11 21): 5
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 3 0): 1
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 8 0): 1
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 9 2): 6
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 13 0): 1
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 9 6): 6
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 14 2): 1
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 11 6): 5
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 11 13): 5
  ("/usr/share/guile/ice-9/debugging/example-fns.scm" 0 0): 3

For profiling, this could be extended to record the time when
evaluation of each source expression begins, and to subtract this from
the time when the frame for each source expression is exited.  The
guile-debugging "at-exit" procedure allows you to do something when a
frame is exited, so `cover-entry' would be extended as follows.

  (use-modules (ice-9 debugging steps))  ; for at-exit

  (define (cover-entry trap-context)
    (let ((source-pos (frame->source-position (tc:frame trap-context)))
          (entry-time #f))
      (if (and source-pos
               (member (car source-pos) covered-file-names))
          (begin
            (hash-set! coverage-hash
                       source-pos
                       (+ (or (hash-ref coverage-hash source-pos) 0) 1))
            (at-exit (tc:depth trap-context)
              (lambda (ignored)
                (hash-set! accumulated-time-hash
                           source-pos
                           (+ (or (hash-ref accumulated-time-hash source-pos) 0)
                              (- (get-time-now) entry-time)))))
            (set! entry-time (get-time-now))))))

I've glossed over details of how to get the current time, and time
arithmetic, so this probably won't work as is, but the intent should
be clear.

It will also be slow, and will incorrectly increase the time of
non-"leaf" code by the time taken by the coverage/profiling code
itself.  guile-statprof does a better job of trying to mitigate the
latter factor, so is in fact a better current bet for profiling Guile
code.

Regards,
     Neil