<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> </div><div>Robby</div></div></div></div><div class="gmail_extra"> <div class="gmail_quote">On Thu, Jul 11, 2013 at 4:07 PM, Joe Gibbs Politz <<a href="mailto:joe@cs.brown.edu" target="_blank">joe@cs.brown.edu</a>> wrote: <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"> 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 ____________________ Racket Users list: <a href="http://lists.racket-lang.org/users" target="_blank">http://lists.racket-lang.org/users</a> </blockquote></div> </div>