[racket] Profiling help
We're trying to profile some slow running programs in a #lang, and
having some trouble getting believable results from the profiler. In
particular, it claims that most (e.g. 60-80%) of the time is spent in
/usr/lib/racket/collects/profile/main.rkt:29:2
We've tried on up to 15-20 second runs of programs, and get the same
result. We've tried making delay shorter (down to 0.01), and turned
on #:threads. We've also tried setting
(compile-context-preservation-enabled) to #t, and (eval-jit-enabled)
to #f, and gotten roughly the same results. Do we need to be running
for minutes or hours? Does the profiler interact badly with `eval`?
We do see *some* calls to the runtime of the language, so they are
recognized, but the time is clearly not being spent all at the top
level of the profiler.
Our test script is essentially:
(time (profile-thunk (lambda ()
(eval-in-our-lang (file->string "some-file"))))
Some sample output is below. We're confident that, for example, our
implementation of `extend` is called quite often (and is attributed
12% of top-of-stack time), but I don't know if I should believe that
proportion with respect to the other functions. Any thoughts on where
that 76% of time is actually spent? Note that about 1/3 of the time
is spent in GC, so maybe that is affecting the times that things are
sampled?
$ racket benchmarks.rkt
Running list-creation
Profiling results
-----------------
Total cpu time observed: 15004ms (out of 15212ms)
Number of samples taken: 568 (once every 26ms)
=============================================================
Caller
Idx Total Self Name+src Local%
ms(pct) ms(pct) Callee
=============================================================
[1] 15004(100.0%) 0(0.0%) [running body]
...ang/src/tests/benchmarks.rkt:##f
run-tests14 [4] 100.0%
-------------------------------------------------------------
map/stx [19] 100.0%
[2] 26(0.2%) 0(0.0%) temp155 (unknown source)
parse-block [18] 100.0%
-------------------------------------------------------------
map/stx [19] 100.0%
[3] 14(0.1%) 0(0.0%) parse-case-branch
...ang/src/lang/parser.rkt:219:0
parse-block [18] 100.0%
-------------------------------------------------------------
[running body] [1] 100.0%
[4] 15004(100.0%) 0(0.0%) run-tests14
...collects/rackunit/text-ui.rkt:243:0
apply-test-suite [5] 100.0%
-------------------------------------------------------------
run-tests14 [4] 100.0%
[5] 15004(100.0%) 0(0.0%) apply-test-suite
...it/private/test-suite.rkt:60:0
the-tests [6] 100.0%
-------------------------------------------------------------
apply-test-suite [5] 100.0%
[6] 15004(100.0%) 0(0.0%) the-tests (unknown source)
profile-thunk12 [7] 100.0%
-------------------------------------------------------------
the-tests [6] 100.0%
[7] 15004(100.0%) 0(0.0%) profile-thunk12
...t/collects/profile/main.rkt:9:0
run [8] 100.0%
-------------------------------------------------------------
profile-thunk12 [7] 100.0%
[8] 15004(100.0%) 11402(76.0%) run
/usr/lib/racket/collects/profile/main.rkt:29:2
extend [9] 12.8%
add-brand [10] 4.2%
string-map-ref5 [14] 4.1%
get-raw-field [11] 2.5%
eval-pyret/check [12] 0.2%
get-field [13] 0.2%
-------------------------------------------------------------
run [8] 100.0%
[9] 1926(12.8%) 1798(12.0%) extend
...ts/pyret-lang/src/lang/runtime.rkt:545:0
foldr [15] 6.6%
-------------------------------------------------------------
run [8] 100.0%
[10] 636(4.2%) 636(4.2%) add-brand
...pyret-lang/src/lang/runtime.rkt:524:0
-------------------------------------------------------------
run [8] 100.0%
[11] 372(2.5%) 372(2.5%) get-raw-field
...t-lang/src/lang/runtime.rkt:439:0
-------------------------------------------------------------
run [8] 100.0%
[12] 26(0.2%) 0(0.0%) eval-pyret/check
.../src/tests/test-utils.rkt:60:0
pyret->racket7 [16] 100.0%
-------------------------------------------------------------
run [8] 100.0%
[13] 24(0.2%) 0(0.0%) get-field
...pyret-lang/src/lang/runtime.rkt:445:0
string-map-ref5 [14] 100.0%
-------------------------------------------------------------
get-field [13] 3.7%
run [8] 96.3%
[14] 642(4.3%) 642(4.3%) string-map-ref5
...ang/src/lang/string-map.rkt:8:0
-------------------------------------------------------------
extend [9] 100.0%
[15] 128(0.9%) 128(0.9%) foldr
...ong/whalesong/lang/private/list.rkt:251:2
-------------------------------------------------------------
eval-pyret/check [12]100.0%
[16] 26(0.2%) 0(0.0%) pyret->racket7
...yret-lang/src/lang/eval.rkt:34:0
parse-program [17] 100.0%
-------------------------------------------------------------
pyret->racket7 [16] 100.0%
[17] 26(0.2%) 0(0.0%) parse-program
...ret-lang/src/lang/parser.rkt:33:0
parse-block [18] 100.0%
-------------------------------------------------------------
parse-case-branch [3] 17.9%
temp155 [2] 41.0%
parse-program [17] 41.0%
[18] 26(0.2%) 0(0.0%) parse-block
...pyret-lang/src/lang/parser.rkt:56:0
map/stx [19] 100.0%
-------------------------------------------------------------
map/stx [19] 10.8%
temp733 [21] 10.8%
parse-block [18] 78.5%
[19] 26(0.2%) 0(0.0%) map/stx
...uts/pyret-lang/src/lang/parser.rkt:28:0
temp155 [2] 33.8%
temp152 [22] 23.1%
temp733 [21] 10.8%
map/stx [19] 10.8%
parse-case-branch [3] 10.8%
temp596 [20] 10.8%
-------------------------------------------------------------
map/stx [19] 100.0%
[20] 14(0.1%) 0(0.0%) temp596 (unknown source)
dots-loop [23] 100.0%
-------------------------------------------------------------
map/stx [19] 100.0%
[21] 14(0.1%) 0(0.0%) temp733 (unknown source)
map/stx [19] 100.0%
-------------------------------------------------------------
map/stx [19] 100.0%
[22] 12(0.1%) 12(0.1%) temp152 (unknown source)
-------------------------------------------------------------
temp596 [20] 100.0%
[23] 14(0.1%) 14(0.1%) dots-loop (unknown source)
-------------------------------------------------------------
cpu time: 15228 real time: 15247 gc time: 5208
![[logo]](/logo.png){kind=logo}