Nothing comes to mind. If you know where the runtime is supposed to start you might try adding printfs in a few places that print out current-process-milliseconds (put a printf right before the call to profile-thunk too) and see if you can kind of hone in on something. You might find something surprising that would give a clue.
Robby On Thu, Jul 11, 2013 at 4:33 PM, Joe Gibbs Politz <j...@cs.brown.edu> wrote: > On Thu, Jul 11, 2013 at 5:22 PM, Robby Findler > <ro...@eecs.northwestern.edu> wrote: > > 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? > > I don't know quite what C-based code we might be touching, but I do > know that our parser down to a racket/base program is no more than a > couple hundred milliseconds for the programs we're working with. I > also tried emitting a more basic Racket module (via pretty-write and > syntax->datum) from a parsed program and profiled that using > `dynamic-require` rather than `eval` and got similar results. > > There are still macros in the emitted program, but there is no > (intended) runtime expansion after the initial macros are dealt with. > > Are there other common C-based code entry points we might be running afoul > of? > > > > > > Robby > > > > > > On Thu, Jul 11, 2013 at 4:07 PM, Joe Gibbs Politz <j...@cs.brown.edu> > wrote: > >> > >> 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: > >> http://lists.racket-lang.org/users > > > > >
____________________ Racket Users list: http://lists.racket-lang.org/users
