instruction-level tracing

instruction-level tracing

[Andy Wingo]

Hi,

I de-bitrotted instruction-level tracing in the VM. Ideally it would
display like ,disassemble does, but that would take some more work.

Still, Guile's speed is mostly proportional to how many instructions are
executed, besides amount of garbage consed, and this view can be
interesting to people looking to squeeze more performance out of their
code, or find ways that the compiler does things wrong.

scheme@(guile-user)> (use-modules (srfi srfi-1))
scheme@(guile-user)> ,trace (fold cons '() '(a b c d)) #:instructions? #t
       0: assert-nargs-ee/locals
       2: load-symbol
      10: link-now
      11: variable-ref
      12: load-symbol
      20: link-now
      21: variable-ref
      22: make-eol
      23: load-symbol
      28: load-symbol
      33: load-symbol
      38: load-symbol
      43: list
      46: tail-call

Tracing wraps a thunk around your form, so the first bit is the body of
that thunk:

   (lambda () (fold cons '() '(a b c d))

Then it starts with the fold itself:

(fold #<procedure cons (_ _)> () (a b c d))
       0: assert-nargs-ge
       3: push-rest
       6: reserve-locals
       9: local-ref
      11: br-if-not-null
      15: br
      49: local-ref
      51: local-ref
      53: local-set
      55: local-set
      57: br
      19: local-ref
      21: br-if-not-null
      28: new-frame
      29: local-ref
      31: local-ref
      33: car
      34: local-ref
      36: call
|(cons a ())
       0: assert-nargs-ee
       3: object-ref
       5: subr-call

Here we see that the cons is not inlined, as we are going through the
subr-call trampoline instead of using the cons instruction directly.

|(a)

This is the result of calling cons... and so on.

      38: local-ref
      40: cdr
      41: local-set
      43: local-set
      45: br
      19: local-ref
      21: br-if-not-null
      28: new-frame
      29: local-ref
      31: local-ref
      33: car
      34: local-ref
      36: call
|(cons b (a))
       0: assert-nargs-ee
       3: object-ref
       5: subr-call
|(b a)
      38: local-ref
      40: cdr
      41: local-set
      43: local-set
      45: br

This sequence, by the way, of local-set + br -- that is the rename +
goto of a tail-call to a local function. Here we have renamed two
variables -- the seed and the list.

      19: local-ref
      21: br-if-not-null
      28: new-frame
      29: local-ref
      31: local-ref
      33: car
      34: local-ref
      36: call
|(cons c (b a))
       0: assert-nargs-ee
       3: object-ref
       5: subr-call
|(c b a)
      38: local-ref
      40: cdr
      41: local-set
      43: local-set
      45: br
      19: local-ref
      21: br-if-not-null
      28: new-frame
      29: local-ref
      31: local-ref
      33: car
      34: local-ref
      36: call
|(cons d (c b a))
       0: assert-nargs-ee
       3: object-ref
       5: subr-call
|(d c b a)
      38: local-ref
      40: cdr
      41: local-set
      43: local-set
      45: br
      19: local-ref
      21: br-if-not-null
      25: local-ref
      27: return
(d c b a)


Have fun,

Andy
-- 
http://wingolog.org/

Re: instruction-level tracing

[Ludovic Courtès]

Hi Andy,

Andy Wingo <wingo@pobox.com> writes:

> I de-bitrotted instruction-level tracing in the VM. Ideally it would
> display like ,disassemble does, but that would take some more work.
>
> Still, Guile's speed is mostly proportional to how many instructions are
> executed, besides amount of garbage consed, and this view can be
> interesting to people looking to squeeze more performance out of their
> code, or find ways that the compiler does things wrong.
>
> scheme@(guile-user)> (use-modules (srfi srfi-1))
> scheme@(guile-user)> ,trace (fold cons '() '(a b c d)) #:instructions? #t

This looks like a useful tool, yes!

Thanks,
Ludo’.