[racket] some weirdness with profiling and the jit

From: Robby Findler (robby at eecs.northwestern.edu)
Date: Tue Mar 6 17:24:30 EST 2012

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


Posted on the users mailing list.