Re: tracing and profiling at the repl

[Andy Wingo]

Hi Neil,

I really must be miscommunicating here :) Let's see if I can do a better
job.

On Tue 22 Dec 2009 22:45, Neil Jerram <address@hidden> writes:

> Andy Wingo <address@hidden> writes:
>
>>     scheme@(guile-user)> ,tr (fibo 5)
>>      #<program 8c74200 at system/vm/trace.scm:30:6 ()>
>>     * #<program 8c74240 at <unknown port>:0:1 ()>
>>     * fibo 5
>>     ** fibo 4
>>     *** fibo 3
>>     **** fibo 2
>>     **** fibo 1
>>     *** fibo 2
>>     ** fibo 3
>>     *** fibo 2
>>     *** fibo 1
>>      #<program 8c741e0 at system/vm/trace.scm:31:6 ()>
>>      vm-trace-off! #<vm 8904680>
>
> - Why are those #<program> and vm-trace-off! lines there?

,tr (short for ,trace) traces *all* function applications that happen
when executing a form. It prints the procedure name and arguments, and
the stack level at that point. If the procedure doesn't have a name, it
just prints the procedure as-is -- thus the #<program ...> lines there.

In fact the #<program> lines there are all the anonymous functions
passed to dynamic-wind in trace.scm. Those lines are there because
tracing is still on until vm-trace-off! gets called.

> - What if the function that you want to trace is not the one that you
>   want to invoke at top level?
>
> - What if you want to trace several functions within a given
>   computation?

This works. You get a lot of output, as things are currently; but we can
restrict tracing to work only on certain procedures, etc.

> - Alternatively, if ,tr is supposed to mean "trace everything within
>   this computation", why aren't there trace lines for the applications
>   of `or', `=' and so on?

Perhaps it would help to disassemble fibo itself:

scheme@(guile-user)> ,x fibo
Disassembly of #<program fibo (x)>:

   0    (assert-nargs-ee 0 1)           
   3    (reserve-locals 0 2)            

Prolog

   6    (local-ref 0)                   ;; `x'
   8    (make-int8:1)                   ;; 1
   9    (ee?)                                                 at (unknown 
file):1:10
  10    (local-set 1)                   ;; `t'
  12    (local-ref 1)                   ;; `t'
  14    (br-if-not :L71)                ;; -> 24
  18    (local-ref 1)                   ;; `t'
  20    (br :L72)                       ;; -> 29
  24    (local-ref 0)                   ;; `x'
  26    (make-int8 2)                   ;; 2
  28    (ee?)                           
  29    (br-if-not :L73)                ;; -> 35              at (unknown 
file):1:2

Is x 1 or 2?

  33    (make-int8:1)                   ;; 1
  34    (return)                        

If so return 1

  35    (new-frame)                                           at (unknown 
file):3:9
  36    (toplevel-ref 1)                ;; `fibo'
  38    (local-ref 0)                   ;; `x'
  40    (sub1)                                                at (unknown 
file):3:15
  41    (call 1)                                              at (unknown 
file):3:9

Otherwise call (fibo (1- x))

  43    (new-frame)                                           at (unknown 
file):4:1
  44    (toplevel-ref 1)                ;; `fibo'
  46    (local-ref 0)                   ;; `x'
  48    (make-int8 2)                   ;; 2
  50    (sub)                                                 at (unknown 
file):4:7
  51    (call 1)                                              at (unknown 
file):4:1

and (fibo (- x 2)

  53    (add)                                                 at (unknown 
file):3:6
  54    (return)

and add and return.

The VM can fire hooks at function application, leaving a function,
entering a new frame, leaving a frame, on "next instruction", and a
couple other places. The tracer hooks into the first four. As you can
see from the disassembly, there is no "or" -- it gets expanded away by
psyntax anyway. = is on lines 9 and 28, inlined into the body. So you
see that the only function that is called is... fibo itself. That's why
it's the only one in the trace.

>> We don't have return values here unfortunately, but that
>> could be arranged.
>
> Yes, I believe they are useful too.

Yep.

>> Now this too:
>>
>>     scheme@(guile-user)> ,pr (fibo 30)
>
> What would someone typing that actually be looking for?  I would guess:
> something about the timings of the internal parts of fibo ...
>
>>     %     cumulative   self             
>>     time   seconds     seconds      name
>>     100.00      0.29      0.29  fibo
>>       0.00      0.29      0.00  top-repl
>>       0.00      0.29      0.00  call-with-backtrace
>>       0.00      0.29      0.00  #<program 8caeb40 ()>
>>       0.00      0.29      0.00  #<program 8ca10e0 opts>
>>       0.00      0.29      0.00  start-repl
>>       0.00      0.29      0.00  #<program 89f3420 at 
>> ice-9/boot-9.scm:3394:10 ()>
>>       0.00      0.29      0.00  #<program 8ca13d0 at 
>> system/repl/repl.scm:87:9 ()>
>>     ---
>>     Sample count: 23
>>     Total time: 0.29 seconds (0 seconds in GC)
>
> ... but there is nothing here at a finer-grained level than fibo
> itself.  So I'm afraid I don't see the usefulness, yet.

As I mentioned making new stacks doesn't work. When that does you will
see:

>>     %     cumulative   self             
>>     time   seconds     seconds      name
>>     100.00      0.29      0.29  fibo
>>     ---
>>     Sample count: 23
>>     Total time: 0.29 seconds (0 seconds in GC)

You can't get any more information on the function call level in this
example, because it's not complicated enough. But try it on anything
else -- (resolve-module '(gnome gtk)) for example:

%     cumulative   self             
time   seconds     seconds      name
 14.18      0.51      0.26  write-bytecode
  9.22      0.17      0.17  #<program 9f1c1e0 at language/scheme/spec.scm:40:16 
(port env)>
  7.09      0.13      0.13  byte-length
  4.26      0.31      0.08  glil->assembly
  2.13      0.17      0.04  dump-object
  2.13      0.15      0.04  #{\get-global-definition-hook\\\ 90}#
  2.13      0.04      0.04  write-byte
  2.13      0.04      0.04  module-ref
  1.42      1.80      0.03  #<program 9e4ed20 at ice-9/boot-9.scm:2039:4 (name 
. args)>
  1.42      0.31      0.03  #{\syntax-type\\\ 162}#
  1.42      0.15      0.03  #<program a10ef50 at language/assembly.scm:63:8 (x 
len)>
  1.42      0.06      0.03  #{\id-var-name\\\ 150}#
  1.42      0.03      0.03  #<program a00a870 at 
language/tree-il/fix-letrec.scm:57:18 (x unref ref set simple lambda* complex)>
  1.42      0.03      0.03  object->assembly
  0.71      1.33      0.01  eval

This is when it had to compile a bunch of things, so really it's a test
of the compiler. Totally useful information though -- we really need to
speed up the bytecode writer!

Regards,

Andy
-- 
http://wingolog.org/