[racket] Profiling help

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 <joe at cs.brown.edu> wrote:

> On Thu, Jul 11, 2013 at 5:22 PM, Robby Findler
> <robby at 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 <joe at 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
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.racket-lang.org/users/archive/attachments/20130711/b785f341/attachment-0001.html>