* statprof working with guile-vm
@ 2009-02-02 22:45 Andy Wingo
2009-02-03 22:57 ` Neil Jerram
0 siblings, 1 reply; 4+ messages in thread
From: Andy Wingo @ 2009-02-02 22:45 UTC (permalink / raw)
To: guile-devel
Dudes and dudettes. Statprof works for profiling guile-vm. If you ask
me, that's pretty sweet.
Here's a profile of loading (oop goops). It's long because, well,
syncase... also I had to increase the sampling frequency because
otherwise the results were really unstable.
scheme@(guile-user)> (use-modules (statprof))
scheme@(guile-user)> (with-statprof #:hz 1000 (resolve-module '(oop goops)))
% cumulative self
time seconds seconds name
15.46 0.05 0.05 eqv?
10.31 0.14 0.04 write-bytecode
3.09 0.09 0.01 glil->assembly
3.09 0.01 0.01 memv
3.09 0.01 0.01 module-make-local-var!
2.06 0.17 0.01 for-each
2.06 0.09 0.01 map
2.06 0.02 0.01 %init-goops-builtins
2.06 0.01 0.01 record-accessor
2.06 0.01 0.01 lookup-transformer
2.06 0.01 0.01 record-predicate
2.06 0.01 0.01 comp
1.03 0.34 0.00 dynamic-wind
1.03 0.03 0.00 translate-1
1.03 0.02 0.00 add-method!
1.03 0.01 0.00 assoc-ref
1.03 0.01 0.00 make-glil-program
1.03 0.01 0.00 comp
1.03 0.00 0.00 syntmp-write-134
1.03 0.00 0.00 syntmp-fk-20
1.03 0.00 0.00 syntmp-fk-31
1.03 0.00 0.00 syntmp-write-byte-18
1.03 0.00 0.00 syntmp-fk-15
1.03 0.00 0.00 syntmp-fk-24
1.03 0.00 0.00 syntmp-write-byte-18
1.03 0.00 0.00 syntmp-fk-35
1.03 0.00 0.00 syntmp-fk-35
1.03 0.00 0.00 syntmp-fk-14
1.03 0.00 0.00 compute-closure-level
1.03 0.00 0.00 syntmp-fk-28
1.03 0.00 0.00 syntmp-fk-13
1.03 0.00 0.00 finish
1.03 0.00 0.00 syntmp-fk-30
1.03 0.00 0.00 comp
1.03 0.00 0.00 dump
1.03 0.00 0.00 syntmp-fk-25
1.03 0.00 0.00 syntmp-fk-18
1.03 0.00 0.00 syntmp-fk-34
1.03 0.00 0.00 syntmp-fk-33
1.03 0.00 0.00 lp
1.03 0.00 0.00 lp
1.03 0.00 0.00 syntmp-fk-13
1.03 0.00 0.00 syntmp-fk-20
1.03 0.00 0.00 syntmp-fk-35
1.03 0.00 0.00 loop
1.03 0.00 0.00 syntmp-fk-14
1.03 0.00 0.00 dump
1.03 0.00 0.00 syntmp-fk-20
1.03 0.00 0.00 syntmp-write-139
1.03 0.00 0.00 loop
1.03 0.00 0.00 syntmp-fk-13
1.03 0.00 0.00 dump
1.03 0.00 0.00 dump
1.03 0.00 0.00 syntmp-fk-34
1.03 0.00 0.00 syntmp-fk-30
1.03 0.00 0.00 close-binding
1.03 0.00 0.00 syntmp-fk-22
1.03 0.00 0.00 syntmp-fk-28
1.03 0.00 0.00 syntmp-fk-22
1.03 0.00 0.00 syntmp-fk-20
1.03 0.00 0.00 syntmp-fk-21
0.00 0.34 0.00 load-compiled/vm
0.00 0.30 0.00 save-module-excursion
0.00 0.30 0.00 load-file
0.00 0.30 0.00 compute-entry-with-cmethod
0.00 0.30 0.00 compile-method/vm
0.00 0.30 0.00 compile-fold
0.00 0.30 0.00 memoize-method!
0.00 0.29 0.00 make-instance
0.00 0.29 0.00 initialize
0.00 0.14 0.00 compile-bytecode
0.00 0.13 0.00 %goops-loaded
0.00 0.13 0.00 make-extended-generic
0.00 0.13 0.00 compute-cmethod
0.00 0.13 0.00 make-next-method
0.00 0.11 0.00 ensure-generic
0.00 0.09 0.00 compile-assembly
0.00 0.09 0.00 compile-asm
0.00 0.05 0.00 byte-length
0.00 0.04 0.00 call-with-ghil-bindings
0.00 0.03 0.00 compile-glil
0.00 0.03 0.00 codegen
0.00 0.02 0.00 lp
0.00 0.02 0.00 lp
0.00 0.01 0.00 lp
0.00 0.01 0.00 lp
0.00 0.01 0.00 comp
0.00 0.01 0.00 lp
0.00 0.01 0.00 lp
0.00 0.01 0.00 lp
0.00 0.01 0.00 lp
0.00 0.01 0.00 retrans
0.00 0.01 0.00 lp
0.00 0.01 0.00 syntmp-fk-810
0.00 0.01 0.00 retrans
0.00 0.01 0.00 comp
0.00 0.01 0.00 call-with-deferred-observers
0.00 0.01 0.00 lp
0.00 0.01 0.00 comp
0.00 0.01 0.00 retrans
0.00 0.01 0.00 make-glil-var
0.00 0.01 0.00 retrans
0.00 0.01 0.00 retrans
0.00 0.01 0.00 retrans
0.00 0.01 0.00 assoc-ref-or-acons
0.00 0.01 0.00 retrans
0.00 0.01 0.00 syntmp-fk-782
0.00 0.01 0.00 comp
0.00 0.00 0.00 loop
0.00 0.00 0.00 syntmp-fk-810
0.00 0.00 0.00 comp
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 push-call!
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 lp
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 lp
0.00 0.00 0.00 lp
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 syntmp-fk-810
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 lp
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 push-call!
0.00 0.00 0.00 retrans
0.00 0.00 0.00 lp
0.00 0.00 0.00 comp
0.00 0.00 0.00 finish
0.00 0.00 0.00 retrans
0.00 0.00 0.00 retrans
0.00 0.00 0.00 comp
0.00 0.00 0.00 resolve-interface
0.00 0.00 0.00 retrans
0.00 0.00 0.00 module-export!
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-33
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-31
0.00 0.00 0.00 call-with-ghil-environment
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-26
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-30
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 retrans
0.00 0.00 0.00 finish
0.00 0.00 0.00 syntmp-fk-29
0.00 0.00 0.00 retrans
0.00 0.00 0.00 write-string
0.00 0.00 0.00 push-call!
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 write-char
0.00 0.00 0.00 syntmp-fk-810
0.00 0.00 0.00 syntmp-fk-810
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-35
0.00 0.00 0.00 syntmp-fk-782
0.00 0.00 0.00 lp
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 retrans
0.00 0.00 0.00 loop
0.00 0.00 0.00 retrans
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 push-call!
0.00 0.00 0.00 syntmp-fk-23
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 retrans
0.00 0.00 0.00 lp
0.00 0.00 0.00 retrans
0.00 0.00 0.00 retrans
0.00 0.00 0.00 retrans
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 lp
0.00 0.00 0.00 push-call!
0.00 0.00 0.00 loop
0.00 0.00 0.00 for-each*
0.00 0.00 0.00 write-string
0.00 0.00 0.00 syntmp-fk-23
0.00 0.00 0.00 write-char
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-17
0.00 0.00 0.00 lp
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 syntmp-fk-31
0.00 0.00 0.00 retrans
0.00 0.00 0.00 retrans
0.00 0.00 0.00 syntmp-fk-13
0.00 0.00 0.00 syntmp-fk-27
0.00 0.00 0.00 syntmp-fk-19
0.00 0.00 0.00 comp-push
0.00 0.00 0.00 retrans
---
Sample count: 97
Total time: 0.34 seconds (7/50 seconds in GC)
$1 = #<directory (oop goops) b7259830>
I'm not yet sure what to make of this. It seems like the compiler itself
can be sped up by a factor of two or so, which sounds nice. We'll see.
Anyway, glad to see that statprof works with the new vm.
Andy
--
http://wingolog.org/
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: statprof working with guile-vm
2009-02-02 22:45 statprof working with guile-vm Andy Wingo
@ 2009-02-03 22:57 ` Neil Jerram
2009-02-04 0:31 ` Andy Wingo
0 siblings, 1 reply; 4+ messages in thread
From: Neil Jerram @ 2009-02-03 22:57 UTC (permalink / raw)
To: Andy Wingo; +Cc: guile-devel
Andy Wingo <wingo@pobox.com> writes:
> Dudes and dudettes. Statprof works for profiling guile-vm. If you ask
> me, that's pretty sweet.
Looks good. And I see some more recent commits on renaming lambdas,
is that to address the multiple occurrences of retrans and lp?
Where is statprof at the moment? If it's now unlikely to change
dramatically, it feels to me that it should move into Guile core.
What do you think?
Regards,
Neil
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: statprof working with guile-vm
2009-02-03 22:57 ` Neil Jerram
@ 2009-02-04 0:31 ` Andy Wingo
2009-02-05 21:05 ` Neil Jerram
0 siblings, 1 reply; 4+ messages in thread
From: Andy Wingo @ 2009-02-04 0:31 UTC (permalink / raw)
To: Neil Jerram; +Cc: guile-devel
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/
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: statprof working with guile-vm
2009-02-04 0:31 ` Andy Wingo
@ 2009-02-05 21:05 ` Neil Jerram
0 siblings, 0 replies; 4+ messages in thread
From: Neil Jerram @ 2009-02-05 21:05 UTC (permalink / raw)
To: Andy Wingo; +Cc: guile-devel
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
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2009-02-05 21:05 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-02-02 22:45 statprof working with guile-vm Andy Wingo
2009-02-03 22:57 ` Neil Jerram
2009-02-04 0:31 ` Andy Wingo
2009-02-05 21:05 ` Neil Jerram
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).