JMH Profilers

JMH contains support for various profilers, which can be selectively enabled when running benchmarks. Those available on your machine/jdk can be listed with jmh.core/profilers. We can also list this information using lein-jmh:

$ lein jmh :profilers

Which, on my machine, yields the following output:

:name       :desc
----------  -----------------------------------------------------------------------------
cl          Classloader profiling via standard MBeans
comp        JIT compiler profiling via standard MBeans
gc          GC profiling via standard MBeans
hs_cl       HotSpot (tm) classloader profiling via implementation-specific MBeans
hs_comp     HotSpot (tm) JIT compiler profiling via implementation-specific MBeans
hs_gc       HotSpot (tm) memory manager (GC) profiling via implementation-specific MBeans
hs_rt       HotSpot (tm) runtime profiling via implementation-specific MBeans
hs_thr      HotSpot (tm) threading subsystem via implementation-specific MBeans
pauses      Pauses profiler
safepoints  Safepoints profiler
stack       Simple and naive Java stack profiler

Let's try a few out. Again, using lein-jmh:

$ lein jmh '{:profilers ["cl" "gc"]}'

Which eventually will emit something like this:

(#_...
 {:fn some.ns/benchmark,
  #_...
  :profilers
  {"class.load" {:samples 10, :score [1.34034 "classes/sec"], :score-error 0.777622},
   #_...
   "gc.time" {:samples 10, :score [40.0 "ms"]}}})

Unfortunately, some profilers don't provide all (or any) of their data in an easily-accessible way. Let's try the "stack" profiler:

$ lein jmh '{:profilers ["stack"]}'

Which yields:

({#_...
  :profilers
  {"stack" {:samples 1, :score [NaN "---"]}}})

What's going on here? It turns out that, currently, this profiler only reports its findings via the JMH raw-text runner format. For profilers like this, we can only see their results by enabling the JMH :status log during our run:

$ lein jmh '{:profilers ["stack"], :status true}'

In this case, the profiler data will labeled with the Stack profiler: sub-heading at the end of the log output under a Secondary result ... header.

Hopefully, in a future JMH version, this reporting deficiency will be addressed.

For more on profiling, I'd recommend this overview blog post.

External profilers

JMH also supports externally defined profiler classes. For example, the spf4j framework provides one that enables Java Flight Recorder for forked JVM processes. To use it, we'll declare a dependency in our project.clj:

Note: as of version 1.25, JMH ships with a built-in JFR profiler.

(defproject our-project "0.1.0-SNAPSHOT"
  #_...
  :dependencies [[org.spf4j/spf4j-jmh "8.3.17"]])

We enable the profiler class by providing its package-prefixed class name in :profilers. Also, since JFR requires an Oracle-branded JVM and I'm using OpenJDK, I'll need to install it and switch the :java binary path. Finally, we need to unlock the Flight Recorder by overriding the forked process :args.

$ lein jmh '
    {:profilers [org.spf4j.stackmonitor.JmhFlightRecorderProfiler]
     :fork {:jvm {:java "/usr/lib/jvm/java-8-oracle/jre/bin/java"  ;; for my Ubuntu 17.10 install
                  :args ["-XX:+UnlockCommercialFeatures"]}}}
  '

If you encounter an IllegalStateException with the message Forked VM failed with exit code 1, or similar when attempting to run, try again with the option flags :status and :verbose set to true to help diagnose the problem. In most cases this will be due to a profiler bug or an incompatible JVM.

By default, this profiler saves the per-benchmark .jfr data files in the current directory (this can be changed by setting the profiler property jmh.stack.profiles via LEIN_JVM_OPTS). We can leverage these dump files via additional tools, foremost of which being Java Mission Control (jmc) provided by Oracle.

Finally, it should be stated that I don't necessarily endorse the above profiler for this particular purpose, it was only used as an example. Also, writing your own profiler for this task is fairly straightforward.