[racket] some weirdness with profiling and the jit

From: Danny Yoo (dyoo at cs.wpi.edu)
Date: Tue Mar 6 15:36:23 EST 2012

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 ...".

Posted on the users mailing list.