環境
- 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の方が速いことがわかった。（この計測方法が正しければ。あと、考慮するべき点がまだまだありそうだが）