[racket] Using the profiler effectively?
I've never been able to use the Racket profiler module effectively,
which makes me very sad.
I want to use it because Whalesong takes way too much time to compile.
I'm looking at: http://docs.racket-lang.org/profile/index.html.
I've been able to run my program with it, and it dumps out an
impressive amount of profiling data.
But I don't know how to interpret the results I'm getting back from
the profiler yet. I guess I'm trying to say: I'm illiterate: I don't
know how to read the textual output of the profiler, and need some
help.
I modified my command line program to run the compiler under the
profiler, and here's a little of what I'm seeing:
$ ~/work/whalesong/whalesong build --enable-profiling tourguide.rkt
Writing program #<path:/home/dyoo/Downloads/akovacs-tourguide/tourguide.js>
Skipping writing resource
#<path:/home/dyoo/Downloads/akovacs-tourguide/index.html>; already
exists
Writing html #<path:/home/dyoo/Downloads/akovacs-tourguide/tourguide.html>
Profiling results
-----------------
Total cpu time observed: 26160ms (out of 26538ms)
Number of samples taken: 418 (once every 63ms)
(Hiding functions with self<1.0% and local<2.0%: 16 of 369 hidden)
===================================================================================
Caller
Idx Total Self Name+src
Local%
ms(pct) ms(pct) Callee
===================================================================================
[1] 26160(100.0%) 0(0.0%) [running body]
...work/whalesong/whalesong.rkt:##f
core [7]
100.0%
-----------------------------------------------------------------------------------
map [120]
16.0%
loop [126]
84.0%
[2] 1576(6.0%) 0(0.0%) parse-def-values
...parse-bytecode-5.1.2.rkt:273:3
parse-lam [8]
80.7%
parse-case-lam [10]
9.6%
parse-let-void [14]
6.3%
parse-with-cont-mark [154]
3.3%
-----------------------------------------------------------------------------------
compile-splice [3]
24.3%
compile [141]
75.7%
[3] 598(2.3%) 48(0.2%) compile-splice
...song/compiler/compiler.rkt:570:0
compile-def-values [9]
75.0%
compile-splice [3]
24.3%
-----------------------------------------------------------------------------------
compile [141]
5.1%
compile-sequence [4]
94.9%
[4] 496(1.9%) 0(0.0%) compile-sequence
...ng/compiler/compiler.rkt:554:0
compile-sequence [4]
94.9%
compile [141]
3.6%
compile-general-application [151]
1.5%
-----------------------------------------------------------------------------------
??? [135]
100.0%
[5] 52(0.2%) 0(0.0%) tree-stuff->row-or-false
...lanet-shared.rkt:104:4
get-info/full [11]
100.0%
-----------------------------------------------------------------------------------
loop [126]
100.0%
[6] 50(0.2%) 0(0.0%) parse-apply-values
...rse-bytecode-5.1.2.rkt:737:3
parse-application [161]
100.0%
-----------------------------------------------------------------------------------
[running body] [1]
100.0%
[7] 26160(100.0%) 0(0.0%) core
...racket-5.1.2/collects/profile/main.rkt:9:0
run [12]
100.0%
-----------------------------------------------------------------------------------
map [120]
9.5%
parse-application [161]
10.7%
parse-def-values [2]
79.9%
[8] 1474(5.6%) 0(0.0%) parse-lam
...parser/parse-bytecode-5.1.2.rkt:512:3
parse-branch [142]
53.7%
parse-seq [13]
19.3%
parse-with-cont-mark [154]
10.0%
parse-let-void [14]
6.8%
extract-lam-name [190]
5.1%
parse-application [161]
5.1%
-----------------------------------------------------------------------------------
compile-splice [3]
100.0%
[9] 496(1.9%) 0(0.0%) compile-def-values
...compiler/compiler.rkt:2001:0
compile-let-void [60]
100.0%
-----------------------------------------------------------------------------------
parse-def-values [2]
100.0%
[10] 152(0.6%) 0(0.0%) parse-case-lam
...r/parse-bytecode-5.1.2.rkt:595:3
map [120]
100.0%
-----------------------------------------------------------------------------------
tree-stuff->row-or-false [5]
100.0%
[11] 52(0.2%) 0(0.0%) get-info/full
...2/collects/setup/getinfo.rkt:28:0
get-info/full/ext [15]
100.0%
-----------------------------------------------------------------------------------
core [7]
100.0%
[12] 26160(100.0%) 0(0.0%) run
...racket-5.1.2/collects/profile/main.rkt:29:2
build-html-and-javascript [16]
100.0%
-----------------------------------------------------------------------------------
I'll cut off the output here, because there's pages and pages of this.
I don't know what I should be looking at. Are the nodes being
printed in any particular order? What else can I do to make the
output sensical? The fact that the function names are getting cut off
with the '...'s is unhelpful.