[racket] some weirdness with profiling and the jit

The profiler uses `continuation-mark-set->context' to determine the
evaluation context for each profiling sample. As I think you know, the
context us computed in different ways with different approximations
when interpreting bytecode versus running JIT-generated code.

More specifically, a JIT-based context is reported if any JIT-based
information is available in the continuation, otherwise the
interpreter-based context is reported. When you start Racket with the
JIT enabled, there's some JIT-based context surrounding the
`parameterize' form, and so it's reported even though the interpreter
context is more complete.

I can imagine adding ways to select the context more explicitly, such
as an extra argument to `continuation-mark-set->context', but I wonder
whether `--no-jit' might be the best way to go overall.

At Tue, 6 Mar 2012 15:36:23 -0500, Danny Yoo 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