CLOVER🍀

That was when it all began.

sbt-jmhを使って、Scalaでマイクロベンチマーク

以前、マイクロベンチマークツールであるJMHを試してみたというエントリを書きました。

JMH
http://openjdk.java.net/projects/code-tools/jmh/

マイクロベンチマークツール、JMHを試す
http://d.hatena.ne.jp/Kazuhira/20140102/1388662362

で、その後Scalaで書こうとして、APTがあるのでJavaのブリッジコードが必要だというエントリを書きました。

Scala+sbtと、JMHを合わせて使う
http://d.hatena.ne.jp/Kazuhira/20140102/1388671010

これに対して、最近@xuwei_kさんからsbtのJMHプラグインができたとツッコミをいただいたので、試してみることにしました。

sbt-jmh

プラグインの名前は、「sbt-jmh」です。

sbt-jmh
https://github.com/ktoso/sbt-jmh

実体は以下の1本のようですが、最終的に実行時(run時)にJavaのコードを生成、コンパイル、実行みたいな動作をします。

https://github.com/ktoso/sbt-jmh/blob/master/src/main/scala/pl/project13/scala/sbt/SbtJmh.scala

とりあえず、使っていってみましょう。あまり深く考えずに、以下のエントリで書いた内容をScalaに移植することを目標にします。

マイクロベンチマークツール、JMHを試す
http://d.hatena.ne.jp/Kazuhira/20140102/1388662362

準備

sbt-jmhはsbtのプラグインとなっているので、まずはplugins.sbtを作成します。
project/plugins.sbt

addSbtPlugin("pl.project13.scala" % "sbt-jmh" % "0.1.4")

あとは、build.sbtを作成。
build.sbt

import JmhKeys._

name := "jhm-scala-example"

version := "0.0.1-SNAPSHOT"

scalaVersion := "2.11.1"

organization := "org.littlewings"

incOptions := incOptions.value.withNameHashing(true)

val jmhVersion = "0.9.2"

libraryDependencies += "org.openjdk.jmh" % "jmh-core" % jmhVersion

jmhSettings

version in Jmh := jmhVersion

outputTarget in Jmh := target.value / s"scala-${scalaBinaryVersion.value}"

若干、カスタム入ってますがとりあえず

import JmhKeys._

として

jmhSettings

があればいいらしいのですが、そもそもソースコードのコンパイル自体にJMHが必要なのと、sbt-jmhが使うJMHのバージョンを変えるために以下のような設定を入れています。

val jmhVersion = "0.9.2"

libraryDependencies += "org.openjdk.jmh" % "jmh-core" % jmhVersion

jmhSettings

version in Jmh := jmhVersion

「version in Jmh」に値を設定しなかった場合、sbt-jmhプラグインのバージョンが0.1.4だった場合、JMH 0.9が使用されます。今回は、0.9.2を使用するようにしました。

また、以下の設定は今回の設定だと入れても入れなくても一緒です。

outputTarget in Jmh := target.value / s"scala-${scalaBinaryVersion.value}"

ベンチマーク対象のコードを作成する

では、以前のエントリからJavaコードをScalaコードに移植して、ベンチマーク対象のコードを書きます。

意味はまったく変わらないので、何をしているかの説明は以下のエントリを参照してください。

マイクロベンチマークツール、JMHを試す
http://d.hatena.ne.jp/Kazuhira/20140102/1388662362

src/main/scala/org/littlewings/jmh/example/HelloJmhScala.scala

package org.littlewings.jmh.example

import java.util.concurrent.TimeUnit

import org.openjdk.jmh.annotations.Benchmark

class HelloJmhScala {
  @Benchmark
  def simpleBench(): Unit =
    TimeUnit.MILLISECONDS.sleep(500L)
}

src/main/scala/org/littlewings/jmh/example/LoopScala.scala

package org.littlewings.jmh.example

import java.util.concurrent.TimeUnit

import org.openjdk.jmh.annotations.Benchmark
import org.openjdk.jmh.annotations.OperationsPerInvocation

class LoopScala {
  def method(limit: Int): Unit = {
    (0 until limit).foreach(_ => TimeUnit.MILLISECONDS.sleep(10))
  }

  @Benchmark
  @OperationsPerInvocation(1)
  def invoke1(): Unit =
    method(1)

  @Benchmark
  @OperationsPerInvocation(100)
  def invoke100(): Unit =
    method(100)
}

src/main/scala/org/littlewings/jmh/example/TestStateScala.scala

package org.littlewings.jmh.example

import org.openjdk.jmh.annotations.{Benchmark, Level, Setup, Scope, State, TearDown}

@State(Scope.Thread)
class TestStateScala {
  private var counter: Long = 0

  @Setup
  //@Setup(Level.Iteration)
  def setup(): Unit = {
    println("========== setup ==========")
    counter = 0
  }

  @Benchmark
  def methodA(): Unit =
    counter += 1

  @Benchmark
  def methodB(): Unit =
    counter += 1

  @TearDown
  //@TearDown(Level.Iteration)
  def tearDown(): Unit = {
    println("========== teardown ==========")
    println("counter = " + counter)
  }
}

取り立てて移植にはそれほど困りませんでしたが、前に使ったJMHのバージョンが0.2で、今回は0.9.2ですがベンチマークを表すアノテーションが変わっていて、そこは読み替えました(@GenerateMicroBenchmark → @Benchmark)。

実行

ベンチマークは、sbtのrunコマンドと引数を使って実行します。特にassemblyプラグインを使ってJARを生成する必要などはないようです。

また、run時にはforkがかかります。

ヘルプの表示。

> run -h
〜省略〜[error] Usage: java -jar ... [regexp*] [options]
[error]  [opt] means optional argument.
[error]  <opt> means required argument.
[error]  "+" means comma-separated list of values.
[error]  "time" arguments accept time suffixes, like "100ms".
[error] 
[error]   [arguments]                 Benchmarks to run (regexp+). 
[error]   -bm <mode>                  Benchmark mode. Available modes are: [Throughput/thrpt, 
[error]                               AverageTime/avgt, SampleTime/sample, SingleShotTime/ss, 
[error]                               All/all]
〜省略〜

ベンチマークの一覧。

> run -l
〜省略〜
[info] Running org.openjdk.jmh.Main -l
[info] Benchmarks: 
[info] org.littlewings.jmh.example.HelloJmhScala.simpleBench
[info] org.littlewings.jmh.example.LoopScala.invoke1
[info] org.littlewings.jmh.example.LoopScala.invoke100
[info] org.littlewings.jmh.example.TestStateScala.methodA
[info] org.littlewings.jmh.example.TestStateScala.methodB

それでは、HelloWorld的なものを動かしてみましょう。

> run org.littlewings.jmh.example.HelloJmhScala.+ -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s

結果。

[info] Running org.openjdk.jmh.Main org.littlewings.jmh.example.HelloJmhScala.+ -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s
[info] # VM invoker: /usr/lib/jvm/java-8-oracle/jre/bin/java
[info] # VM options: <none>
[info] # Warmup: 3 iterations, 1 s each
[info] # Measurement: 3 iterations, 1 s each
[info] # Threads: 1 thread, will synchronize iterations
[info] # Benchmark mode: Throughput, ops/time
[info] # Benchmark: org.littlewings.jmh.example.HelloJmhScala.simpleBench
[info] 
[info] # Run progress: 0.00% complete, ETA 00:00:06
[info] # Fork: 1 of 1
[info] # Warmup Iteration   1: 1.998 ops/s
[info] # Warmup Iteration   2: 1.995 ops/s
[info] # Warmup Iteration   3: 1.996 ops/s
[info] Iteration   1: 1.996 ops/s
[info] Iteration   2: 1.997 ops/s
[info] Iteration   3: 1.998 ops/s
[info] 
[info] 
[info] Result: 1.997 ±(99.9%) 0.022 ops/s [Average]
[info]   Statistics: (min, avg, max) = (1.996, 1.997, 1.998), stdev = 0.001
[info]   Confidence interval (99.9%): [1.975, 2.019]
[info] 
[info] 
[info] # Run complete. Total time: 00:00:09
[info] 
[info] Benchmark                             Mode   Samples        Score  Score error    Units
[info] o.l.j.e.HelloJmhScala.simpleBench    thrpt         3        1.997        0.022    ops/s

ちょっと以前のバージョンと、表示が変わりましたね。引数の意味などは、以前のエントリを参照してください。

繰り返しのベンチマークを実行。

> run org.littlewings.jmh.example.LoopScala.+ -wi 3 -i 3 -f 1 -r 1s -bm all -tu s

結果。

[info] # Run complete. Total time: 00:01:06
[info] 
[info] Benchmark                       Mode   Samples        Score  Score error    Units
[info] o.l.j.e.LoopScala.invoke1      thrpt         3       88.939       29.343    ops/s
[info] o.l.j.e.LoopScala.invoke100    thrpt         3       89.491       51.835    ops/s
[info] o.l.j.e.LoopScala.invoke1       avgt         3        0.011        0.003     s/op
[info] o.l.j.e.LoopScala.invoke100     avgt         3        0.011        0.003     s/op
[info] o.l.j.e.LoopScala.invoke1     sample       284        0.011        0.000     s/op
[info] o.l.j.e.LoopScala.invoke100   sample         3        0.011        0.004     s/op
[info] o.l.j.e.LoopScala.invoke1         ss         3        0.012        0.021        s
[info] o.l.j.e.LoopScala.invoke100       ss         3        1.123        0.877        s

状態を持たせたベンチマーク。

> run org.littlewings.jmh.example.TestStateScala.+ -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s

結果。

[info] Result: 382742653.005 ±(99.9%) 426391567.957 ops/s [Average]
[info]   Statistics: (min, avg, max) = (355927973.628, 382742653.005, 398791634.469), stdev = 23371960.634
[info]   Confidence interval (99.9%): [-43648914.951, 809134220.962]
[info] 
[info] 
[info] # Run complete. Total time: 00:00:16
[info] 
[info] Benchmark                          Mode   Samples        Score  Score error    Units
[info] o.l.j.e.TestStateScala.methodA    thrpt         3 374397237.327 597683389.117    ops/s
[info] o.l.j.e.TestStateScala.methodB    thrpt         3 382742653.005 426391567.957    ops/s

結果、どれもそんなに変わらないから大丈夫かな…。

とりあえず、使えそうですね。

ちょっと気になったこと

JMH自体を使っていればそれほどハマりどころはないような気はするものの、ちょっと気になったのが実行時の挙動。

runコマンドで実行すると、必ず以下のようなログが出力されます。

> run org.littlewings.jmh.example.TestStateScala.+ -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s
[info] Compiling 3 Scala sources to /xxxxx/jmh-scala-example/target/scala-2.11/classes...
[info] Generating JMH benchmark Java source files...
Processing 4 classes from /xxxxx/jmh-scala-example/target/scala-2.11/classes with "reflection" generator
Writing out Java source to /xxxxx/jmh-scala-example/target/scala-2.11/generated-sources/jmh and resources to /xxxxx/jmh-scala-example/target/scala-2.11/classes
[info] Compiling generated JMH benchmarks...
[info] Compiling 3 Scala sources and 5 Java sources to /xxxxx/jmh-scala-example/target/scala-2.11/classes...

で、ここからベンチマーク実行開始。

[info] Running org.openjdk.jmh.Main org.littlewings.jmh.example.TestStateScala.+ -wi 3 -i 3 -f 1 -r 1s -bm thrpt -tu s

前回のコンパイル有無に関わらず、毎回Javaのコード生成が走ります。ヘルプを見るのにも、コード生成が走ります。ベンチマークの一覧を見るのにも、やっぱり走ります。というか、本体のコードもコンパイルされているような…。

まあ仕方がないのかなーという気もしますけどね…。