[racket] some weirdness with profiling and the jit
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 ...".