[racket] some weirdness with profiling and the jit

I'm not sure of the answer, but you might have better results if you
work directly with the primitives that the profiler is using, namely
calling continuation-marks directly at some point where things are
funny and seeing what you get from contination-mark-set->context on
those marks in different contexts.

Robby

On Tue, Mar 6, 2012 at 2:36 PM, Danny Yoo <dyoo at cs.wpi.edu> wrote:
> I'm noticing some significant difference in the output of the
> statistical profiler with regards to the JIT.  I wanted to normalize
> this effect by creating an environment for dynamic evaluation, hoping
> that setting the right parameters would get me the same effect.
>
> Here's a `run-profiler.rkt` tool I cooked up that is meant to run the
> profiler under a non-jitting context:
>
> ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
> #lang racket/base
>
> (require syntax/strip-context)
>
> (define modname (vector-ref (current-command-line-arguments) 0))
>
> (parameterize ([compile-context-preservation-enabled #t]
>               [compile-enforce-module-constants #f]
>               [use-compiled-file-paths '()]
>               [load-on-demand-enabled #f]
>               [eval-jit-enabled #f])
>  (parameterize ([current-namespace (make-base-namespace)])
>    (with-syntax ([modname modname])
>      (eval (strip-context #'(module anonymous racket/base
>                               (require profile)
>                               (require modname)
>                               (profile
>                                (call-with-continuation-prompt run)))))
>      (eval (strip-context #'(require 'anonymous))))))
> ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
>
>
>
> Unfortunately, it doesn't quite work as well as I'd like.  When I use
> it to evaluate a small test bed, I see the following:
>
> ####################################################################
> $ racket run-profiler.rkt runner.rkt
> Profiling results
> -----------------
>  Total cpu time observed: 4110ms (out of 4596ms)
>  Number of samples taken: 56 (once every 73ms)
>
> ======================================================
>                              Caller
> Idx   Total       Self      Name+src            Local%
>      ms(pct)     ms(pct)     Callee
> ======================================================
> [1] 3422(83.3%)    0(0.0%)  [running body] ...er-tutorial/run-profiler.rkt:##f
>                              [running body] [3]100.0%
> ------------------------------------------------------
> [2]  688(16.7%)    0(0.0%)  run ...dyoo/work/profiler-tutorial/runner.rkt:18:0
>                              my-flatten [4]    100.0%
> ------------------------------------------------------
>                              [running body] [1]100.0%
> [3] 3422(83.3%) 3422(83.3%) [running body] anonymous:##f
> ------------------------------------------------------
>                              run [2]             0.0%
>                              my-flatten [4]    100.0%
> [4]  688(16.7%)    0(0.0%)  my-flatten ...profiler-tutorial/my-flatten.rkt:7:0
>                              my-flatten [4]    100.0%
>                              my-append [5]       0.0%
> ------------------------------------------------------
>                              my-flatten [4]    100.0%
> [5]  688(16.7%)  688(16.7%) my-append .../profiler-tutorial/my-flatten.rkt:4:0
> ------------------------------------------------------
>
> ####################################################################
>
>
> Note that a large part of the "self-runtime" is being attributed to
> the "running body" of the anonymous module that I'm generating
> dynamically.  That's not right.  When I run racket with the "--no-jit"
> option, I get significantly better output:
>
>
> ####################################################################
> kui ~/work/profiler-tutorial $ racket --no-jit run-profiler.rkt runner.rkt
> Profiling results
> -----------------
>  Total cpu time observed: 5381ms (out of 6985ms)
>  Number of samples taken: 38 (once every 142ms)
>
> ====================================================
>                                Caller
> Idx   Total        Self       Name+src        Local%
>      ms(pct)      ms(pct)      Callee
> ====================================================
> [1] 5381(100.0%)    0(0.0%)   run ...dyoo/work/profiler-tutorial/runner.rkt:18:0
>                                my-flatten [2]100.0%
> ----------------------------------------------------
>                                run [1]         0.0%
>                                my-flatten [2]100.0%
> [2] 5381(100.0%)    0(0.0%)   my-flatten ...profiler-tutorial/my-flatten.rkt:7:0
>                                my-flatten [2]100.0%
>                                my-append [3]   0.0%
> ----------------------------------------------------
>                                my-flatten [2]100.0%
> [3] 5381(100.0%) 5381(100.0%) my-append .../profiler-tutorial/my-flatten.rkt:4:0
> ----------------------------------------------------
> ####################################################################
>
>
> This result properly attributes time to the function I intended to be
> the hotspot.  So it looks like when I run the profiler under
> "--no-jit", I get better results.  However, I'm trying to understand
> why the things I'm doing in run-profiler.rkt don't have the same
> effect as if I were running "racket --no-jit ...".
> ____________________
>  Racket Users list:
>  http://lists.racket-lang.org/users