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