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 <n...@ossau.uklinux.net> writes:
> Andy Wingo <wi...@pobox.com> 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/
