環境

macOS Mojava 10.14.4
Scala 2.13.1
sbt 1.3.8
GraalVM 20.1

この前の測定の大雑把な問題点

前回の記事で、GraalVmと標準JVMの速度比較を行った。

しかし、コンパイル時間・ウォームアップ時間・純粋な実行時間をごちゃ混ぜにして測定していたので、Graal自体の純粋な速度比較ができていなかった。

今回やりたいことは、GraalVMのGraalと、標準JVMのC2コンパイラでの速度比較。

なので、コンパイル（クラスファイル生成）・ウォームアップ・純粋な実行時間をそれぞれ区別して、純粋な実行時間の比較を行う。

具体的な問題点

1.コンパイル（クラスファイル生成）時間も含めていた。

sbtで実行する場合、実行する前に、まぜクラスファイルを生成してあげてから、計測する。

$ sbt compile
$ sbt run

2. ウォームアップ処理と、コンパイル後の処理がぐちゃぐちゃに計測されていた。

この記事でも書いている通り、JVMはクラスファイルを、まずインタプリンタで実行（ウォームアップ）し、コンパイルに必要な情報が集まってからJITコンパイラが対象のメソッドをコンパイルする作りになっている。

GraalやC2コンパイラの純粋な実行速度を計測するには、対象のメソッドをウォームアップ->コンパイル後の速度を計測しなければいけない。

この本によると、JITコンパイラの　インタプリンタからJITコンパイラへの切替の閾値が、8000回となっている。
つまり、対象にメソッドを8000回以上実行（ウォームアップ）してあげると、そのメソッドがJITコンパイラによってコンパイルされるので、そのコンパイルされたコードの速度計測をすると言うわけ。

JMHを使って速度測定する

前回は、/usr/bin/timeコマンドで測定を行った。
しかし、それでは純粋な速度比較が行えないので、JMHを使って、正確な数値を出す。

sbtのライブラリがあるので、それを利用した。

測定するコード

テキストファイルから英文を読み込んで、頻繁に利用されている単語上位１０個を吐き出すプログラム。

├── resources
│   └── GraalTest.txt
└── scala
    └── graal
        └── Performance.scala

テキストファイル。
適当な英文を持ってきた。

Graal.txt

When people talk about Japan, they would always think about how innovative and technological this country gets! Or how pretty and neat the country is! Last but not the least, fashion, Cosplay and hype beast were always a big thing in the city of Japan. Coming to Japan with the intention of tourism would have been a great experience. Different culture. You can find a lot of unique things they sell in Japan! But as you live in Japan, you interact with the locals and everything doesn’t seem the way you thought of Japan.

大きさは、525B。

$ ll
-rw-r--r--  1 kinsho  staff   525B  6 14 10:18 GraalTest.txt

JMHライブラリでは、アノテーションで測定オプションを指定できる。
以下のように設定した。

ウォームアップ回数
対象のメソッドに対して、10000回の実行を1回行う。
上述したように、8000回の実行を超えると、JITコンパイラにより対象のメソッドがコンパイルされるので、とりあえず10000回ウォームアップしておく。
実行回数
対象のメソッドに対して、10000回の実行を３０回行う。
公式ドキュメントに、10~20のイテレーションを行うと、現実的な数字が出ると書いている。

Performance.scala


package graal

import java.util.concurrent.TimeUnit

import org.openjdk.jmh.annotations._

import scala.annotation.tailrec
import scala.io.BufferedSource

// フォーク数を指定
// デフォルトは5
@Fork(1)
@Warmup(iterations = 1, batchSize = 10000)
@Measurement(iterations = 30, batchSize = 10000)
// 1回あたりの実行時間を測定する
@BenchmarkMode(Array(Mode.SingleShotTime))
// 計測単位をms
@OutputTimeUnit(TimeUnit.MILLISECONDS)
class GraalTest {

  // このメソッドを測定対象にする
  @Benchmark
  def run = {
    val fileName: String = "GraalTest.txt"
    val encode: String = "UTF-8"
    val source: BufferedSource = scala.io.Source.fromResource(fileName)
    val lines: Iterator[String] = source.getLines()
    val sortedTextList = lines.toList.mkString(" ").split(" ").sorted.toList
    val value = createMap(sortedTextList)
    val top10Words = value.toList.sortBy(_._2).reverse.take(10)
  }

  private def createMap(wordList: List[String]): Map[String, Long] = {
    @tailrec
    def loop(list: List[String], acc: Map[String, Long]): Map[String, Long] = {
      list match {
        case head :: tail if acc.isEmpty => {
          loop(tail, acc + (head -> 1L))
        }
        case head :: tail => {
          acc.get(head) match {
            case Some(value) => {
              loop(tail, acc.updated(head, value + 1L))
            }
            case None => {
              loop(tail, acc + (head -> 1L))
            }
          }
        }
        case head :: Nil => {
          acc.get(head) match {
            case Some(value) => {
              acc.updated(head, value + 1L)
            }
            case None => {
              acc + (head -> 1L)
            }
          }
        }
        case Nil => acc
      }
    }
    loop(wordList, Map.empty[String, Long])
  }
}

標準JVMで実行

まず、コンパイルする

sbt:jitCompiler> jmh:compile
[info] Compiling 3 Scala sources to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/classes ...
...
[info] Compiling 5 Java sources to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/classes ...
[success] Total time: 5 s, completed 2020/06/14 12:08:28

実際に実行する。
[info] # VM version: JDK 1.8.0_232, OpenJDK 64-Bit Server VM, 25.232-b09から、標準JVMを利用して実行していることが分かる。

sbt:jitCompiler> jmh:run
[info] running (fork) org.openjdk.jmh.Main
[info] # JMH version: 1.21
[info] # VM version: JDK 1.8.0_232, OpenJDK 64-Bit Server VM, 25.232-b09
[info] # VM invoker: /Library/Java/JavaVirtualMachines/adoptopenjdk-8.jdk/Contents/Home/jre/bin/java
[info] # VM options: <none>
[info] # Warmup: 1 iterations, single-shot each, 10000 calls per op
[info] # Measurement: 30 iterations, single-shot each, 10000 calls per op
[info] # Timeout: 10 min per iteration
[info] # Threads: 1 thread
[info] # Benchmark mode: Single shot invocation time
[info] # Benchmark: graal.GraalTest.run
[info] # Run progress: 0.00% complete, ETA 00:00:00
[info] # Fork: 1 of 1
[info] # Warmup Iteration   1: 1075.011 ms/op
[info] Iteration   1: 555.518 ms/op
[info] Iteration   2: 634.679 ms/op
[info] Iteration   3: 552.381 ms/op
[info] Iteration   4: 687.170 ms/op
[info] Iteration   5: 538.699 ms/op
[info] Iteration   6: 537.693 ms/op
[info] Iteration   7: 622.123 ms/op
[info] Iteration   8: 801.559 ms/op
[info] Iteration   9: 611.831 ms/op
[info] Iteration  10: 567.022 ms/op
[info] Iteration  11: 590.506 ms/op
[info] Iteration  12: 666.859 ms/op
[info] Iteration  13: 564.290 ms/op
[info] Iteration  14: 552.446 ms/op
[info] Iteration  15: 713.195 ms/op
[info] Iteration  16: 781.514 ms/op
[info] Iteration  17: 685.628 ms/op
[info] Iteration  18: 570.931 ms/op
[info] Iteration  19: 557.543 ms/op
[info] Iteration  20: 559.926 ms/op
[info] Iteration  21: 677.823 ms/op
[info] Iteration  22: 551.438 ms/op
[info] Iteration  23: 564.687 ms/op
[info] Iteration  24: 560.043 ms/op
[info] Iteration  25: 553.672 ms/op
[info] Iteration  26: 548.359 ms/op
[info] Iteration  27: 777.705 ms/op
[info] Iteration  28: 794.434 ms/op
[info] Iteration  29: 917.850 ms/op
[info] Iteration  30: 553.160 ms/op
[info] Result "graal.GraalTest.run":
[info]   N = 30
[info]   mean =    628.356 ±(99.9%) 67.159 ms/op
[info]   Histogram, ms/op:
[info]     [ 500.000,  550.000) = 3
[info]     [ 550.000,  600.000) = 14
[info]     [ 600.000,  650.000) = 3
[info]     [ 650.000,  700.000) = 4
[info]     [ 700.000,  750.000) = 1
[info]     [ 750.000,  800.000) = 3
[info]     [ 800.000,  850.000) = 1
[info]     [ 850.000,  900.000) = 0
[info]     [ 900.000,  950.000) = 1
[info]   Percentiles, ms/op:
[info]       p(0.0000) =    537.693 ms/op
[info]      p(50.0000) =    568.977 ms/op
[info]      p(90.0000) =    793.142 ms/op
[info]      p(95.0000) =    853.890 ms/op
[info]      p(99.0000) =    917.850 ms/op
[info]      p(99.9000) =    917.850 ms/op
[info]      p(99.9900) =    917.850 ms/op
[info]      p(99.9990) =    917.850 ms/op
[info]      p(99.9999) =    917.850 ms/op
[info]     p(100.0000) =    917.850 ms/op
[info] # Run complete. Total time: 00:00:26
[info] REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
[info] why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
[info] experiments, perform baseline and negative tests that provide experimental control, make sure
[info] the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
[info] Do not assume the numbers tell you what you want them to tell.
[info] Benchmark      Mode  Cnt    Score    Error  Units
[info] GraalTest.run    ss   30  628.356 ± 67.159  ms/op
[success] Total time: 26 s, completed 2020/06/14 12:26:25

標準JVMでの結果

結果がズラーっと記載されているが、まとめると、

ウォームアップ時間：1075.011 ms/op
純粋な速度：628.356 ms/op

ms/opは、対象メソッド一回の実行に対して、どれくらい時間がかかったのかを表す単位。
純粋な速度よりも、ウォームアップ時間の方が時間がかかっているので、10000回のウォームアップ後、正常にコンパイルされていることもわかる。

GraalVMで実行する

今度は本命、GraalVMで測定！
まず、コンパイルする。

sbt:jitCompiler> jmh:compile
[info] Compiling 3 Scala sources to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/classes ...
...
[info] Compiling 5 Java sources to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/classes ...
[success] Total time: 5 s, completed 2020/06/14 12:18:06

実行する。


sbt:jitCompiler> jmh:run
Processing 9 classes from /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/classes with "reflection" generator
Writing out Java source to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/src_managed/jmh and resources to /Users/kinsho/workspace/loginfrastructure/jitCompiler/target/scala-2.13/resource_managed/jmh
[info] running (fork) org.openjdk.jmh.Main
[info] # JMH version: 1.21
[info] # VM version: JDK 1.8.0_252, OpenJDK 64-Bit Server VM GraalVM CE 20.1.0, 25.252-b09-jvmci-20.1-b02
[info] # VM invoker: /Library/Java/JavaVirtualMachines/graalvm-ce-java8-20.1.0/Contents/Home/jre/bin/java
[info] # VM options: <none>
[info] # Warmup: 1 iterations, single-shot each, 10000 calls per op
[info] # Measurement: 30 iterations, single-shot each, 10000 calls per op
[info] # Timeout: 10 min per iteration
[info] # Threads: 1 thread
[info] # Benchmark mode: Single shot invocation time
[info] # Benchmark: graal.GraalTest.run
[info] # Run progress: 0.00% complete, ETA 00:00:00
[info] # Fork: 1 of 1
[info] # Warmup Iteration   1: 1012.169 ms/op
[info] Iteration   1: 546.073 ms/op
[info] Iteration   2: 584.707 ms/op
[info] Iteration   3: 547.958 ms/op
[info] Iteration   4: 662.077 ms/op
[info] Iteration   5: 549.202 ms/op
[info] Iteration   6: 490.277 ms/op
[info] Iteration   7: 620.376 ms/op
[info] Iteration   8: 780.583 ms/op
[info] Iteration   9: 576.626 ms/op
[info] Iteration  10: 508.686 ms/op
[info] Iteration  11: 543.451 ms/op
[info] Iteration  12: 589.145 ms/op
[info] Iteration  13: 515.498 ms/op
[info] Iteration  14: 524.002 ms/op
[info] Iteration  15: 717.083 ms/op
[info] Iteration  16: 839.723 ms/op
[info] Iteration  17: 523.987 ms/op
[info] Iteration  18: 519.271 ms/op
[info] Iteration  19: 525.304 ms/op
[info] Iteration  20: 530.935 ms/op
[info] Iteration  21: 634.322 ms/op
[info] Iteration  22: 545.711 ms/op
[info] Iteration  23: 513.338 ms/op
[info] Iteration  24: 518.737 ms/op
[info] Iteration  25: 519.130 ms/op
[info] Iteration  26: 575.139 ms/op
[info] Iteration  27: 745.525 ms/op
[info] Iteration  28: 774.832 ms/op
[info] Iteration  29: 830.160 ms/op
[info] Iteration  30: 549.396 ms/op
[info] Result "graal.GraalTest.run":
[info]   N = 30
[info]   mean =    596.708 ±(99.9%) 68.925 ms/op
[info]   Histogram, ms/op:
[info]     [400.000, 450.000) = 0
[info]     [450.000, 500.000) = 1
[info]     [500.000, 550.000) = 16
[info]     [550.000, 600.000) = 4
[info]     [600.000, 650.000) = 2
[info]     [650.000, 700.000) = 1
[info]     [700.000, 750.000) = 2
[info]     [750.000, 800.000) = 2
[info]     [800.000, 850.000) = 2
[info]   Percentiles, ms/op:
[info]       p(0.0000) =    490.277 ms/op
[info]      p(50.0000) =    548.580 ms/op
[info]      p(90.0000) =    780.008 ms/op
[info]      p(95.0000) =    834.463 ms/op
[info]      p(99.0000) =    839.723 ms/op
[info]      p(99.9000) =    839.723 ms/op
[info]      p(99.9900) =    839.723 ms/op
[info]      p(99.9990) =    839.723 ms/op
[info]      p(99.9999) =    839.723 ms/op
[info]     p(100.0000) =    839.723 ms/op
[info] # Run complete. Total time: 00:00:25
[info] REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
[info] why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
[info] experiments, perform baseline and negative tests that provide experimental control, make sure
[info] the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
[info] Do not assume the numbers tell you what you want them to tell.
[info] Benchmark      Mode  Cnt    Score    Error  Units
[info] GraalTest.run    ss   30  596.708 ± 68.925  ms/op
[success] Total time: 26 s, completed 2020/06/14 12:22:50

GraalVmでの結果

今回も結果がズラーっと記載されているが、まとめると、

ウォームアップ時間：1012.169 ms/op
純粋な実行時間：596.708 ms/op

全体結果

測定結果、Graalの方が速いことがわかった。（この計測方法が正しければ。あと、考慮するべき点がまだまだありそうだが）

参考