Re: statprof working with guile-vm

[Neil Jerram <neil@ossau.uklinux.net>]

Andy Wingo <wingo@pobox.com> writes:

> No. Statprof reports procedures by identity (i.e. `eq?'), not by name;
> but it discards procedures that have no names on the grounds that you
> don't really know what those procedures are.

So why were there so many entries for `retrans', then?  (I assume
there's really one `retrans' procedure in the system?)

> That commit was to give names to procedures bound like (letrec ((foo
> (lambda ...)))).

OK.

> But come to think of it, we should be able to do better, reporting based
> on identity of source location (as determined for example by eq? on
> program-objcode, or on interpreted closure code) instead of on procedure
> (closure) identity.

Yes, that could be nice.

>> Where is statprof at the moment?
>
> Guile-lib
>
>> If it's now unlikely to change dramatically, it feels to me that it
>> should move into Guile core. What do you think?
>
> I agree, though there are some documentation things to take care of. It
> was only written by Rob Browning, and modified a bit by myself.

I'll add it to my list too, then.  (But it's a long list...)

> Statprof on the vm is slightly different due to tail recursion -- the
> debugging evaluator keeps some of those frames on the debug stack.
> Surprising.

That the evaluator keeps debug info for those frames, you mean?

> Also here's the current GOOPS profile:
>
>     scheme@(guile-user)> (use-modules (statprof))
>     scheme@(guile-user)> (with-statprof #:hz 1000 (resolve-module '(oop goops)))
>     %     cumulative   self             
>     time   seconds     seconds      name
>      18.18      0.10      0.04  for-each
>       7.58      0.03      0.02  byte-length
>       7.58      0.02      0.02  record-predicate
>       4.55      0.06      0.01  glil->assembly
>       3.03      0.21      0.01  load-compiled/vm
>       3.03      0.08      0.01  write-bytecode
>       3.03      0.01      0.01  lookup-transformer
>       3.03      0.01      0.01  ghil-env-add!
>       3.03      0.01      0.01  list-index
>       3.03      0.01      0.01  cache-try-hash!
>       1.52      0.05      0.00  map
>       1.52      0.01      0.00  lp
>       1.52      0.01      0.00  make-glil-program
>       1.52      0.01      0.00  eqv?
>       1.52      0.01      0.00  %init-goops-builtins
>       [...]
>       0.00      0.21      0.00  dynamic-wind
>       0.00      0.20      0.00  memoize-method!
>       0.00      0.19      0.00  compute-entry-with-cmethod
>       0.00      0.19      0.00  compile-fold
>       0.00      0.19      0.00  compile-method/vm
>       0.00      0.18      0.00  make-instance
>       0.00      0.18      0.00  initialize
>       0.00      0.08      0.00  compute-cmethod
>       0.00      0.08      0.00  %goops-loaded
>       0.00      0.08      0.00  make-extended-generic
>       0.00      0.08      0.00  make-next-method
>       0.00      0.08      0.00  compile-bytecode
>       0.00      0.06      0.00  ensure-generic
>       0.00      0.06      0.00  compile-asm
>       0.00      0.06      0.00  compile-assembly
>       0.00      0.04      0.00  save-module-excursion
>       0.00      0.03      0.00  compile-glil
>       0.00      0.03      0.00  codegen
>       0.00      0.02      0.00  call-with-ghil-bindings
>       0.00      0.02      0.00  load-file
>       0.00      0.02      0.00  add-method!
>       0.00      0.02      0.00  translate-1
>       0.00      0.01      0.00  record-accessor
>       [...]
>       Sample count: 66
>       Total time: 0.21 seconds (2/25 seconds in GC)
>
> I think the salient point here is that out of 0.21 seconds of loading
> GOOPS, 0.19 of it is spent in the compiler (see `compile-fold').

Do you mean that this is the VM compiler compiling closures that GOOPS
creates dynamically?

(As is probably clear, I don't think I understand yet!)

Regards,
        Neil