Re: statprof working with guile-vm

[Andy Wingo <wingo@pobox.com>]

On Tue 03 Feb 2009 23:57, Neil Jerram <neil@ossau.uklinux.net> writes:

> Andy Wingo <wingo@pobox.com> writes:
>
>> Statprof works for profiling guile-vm.
>
> Looks good.

Thanks.

> And I see some more recent commits on renaming lambdas, is that to
> address the multiple occurrences of retrans and lp?

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.

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

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.

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

Statprof on the vm is slightly different due to tail recursion -- the
debugging evaluator keeps some of those frames on the debug stack.
Surprising. 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').

Besides that, there are like 60000 closures created, which is a bit
excessive. That number is from valgrind. Also these numbers do match
well with the valgrind numbers.  I think there's still 10-20% of
low-hanging fruit, but the algorithmic improvements are really where
we're going to win.

Anyway, late night ramblings.

Hasta luego,

Andy
-- 
http://wingolog.org/