[racket] Using the profiler effectively?

From: Danny Yoo (dyoo at cs.wpi.edu)
Date: Sun Sep 4 19:38:41 EDT 2011

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.


Posted on the users mailing list.