Re: tracing and profiling at the repl

[Neil Jerram]

Andy Wingo <address@hidden> writes:

> Hi Neil,
>
> I really must be miscommunicating here :)

I think you just left out a couple of details.  Plus I think you're
assuming that there is no requirement (or usefulness) for tracing or
profiling below the program level - i.e. within a sequence of VM
operations.

Is that assumption correct?  Doesn't it mean that we can profile/trace
less as the compiler becomes cleverer?

> Let's see if I can do a better job.

Thank you! :-)

> ,tr (short for ,trace) traces *all* function applications that happen
> when executing a form.

OK.

>> - 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.

That sounds good.  I would suggest that we allow for any combination of

- some procedures for which only call+args and return value are
  traced

- some procedures for which all applications within the dynamic context
  of those procedures are traced

- some top-level computation (presumably including some of the previous
  procedures), for which the tracing function is enabled.

>> - 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:

[...]

> 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.

Thanks for the detailed explanation.  I understand, but I wonder (as
also above) if this will be useful enough in practice.

> 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!

Yes, that's pretty nice.

I'm just not sure how things work as the generated code becomes more
optimised.  For example, when a `map' procedure is inlined.  But maybe
that's a fundamental problem, and it's well known (except to me!) that
you can't unambiguously trace or profile optimised code.

> Regards,
>
> Andy

Regards,
        Neil