Tweet
Tweet

Slide 1

Slide 1 text

ScalaMeter Performance regression testing framework Aleksandar Prokopec, Josh Suereth, Vlad Ureche, Roman Zoller, Ngoc Duy Pham, Alexey Romanov, Roger Vion, Eugene Platonov, Lukas Rytz, Paolo Giarusso, Dan Burkert, Christian Krause, and others

Slide 2

Slide 2 text

Background

Slide 3

Slide 3 text

Background Georges A., Buytaert D., Eeckhout L. Statistically rigorous Java performance evaluation. OOPSLA '07

Slide 4

Slide 4 text

Motivation List(1 to 100000: _*).map(x => x * x) 26 ms

Slide 5

Slide 5 text

Motivation List(1 to 100000: _*).map(x => x * x) class List[+T] extends Seq[T] { // implementation 1 } 26 ms

Slide 6

Slide 6 text

Motivation List(1 to 100000: _*).map(x => x * x) class List[+T] extends Seq[T] { // implementation 1 } 26 ms

Slide 7

Slide 7 text

Motivation List(1 to 100000: _*).map(x => x * x) class List[+T] extends Seq[T] { // implementation 2 } 49 ms

Slide 8

Slide 8 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) }

Slide 9

Slide 9 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) }

Slide 10

Slide 10 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) }

Slide 11

Slide 11 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) }

Slide 12

Slide 12 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) } measure()

Slide 13

Slide 13 text

First example def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) } measure() 26 ms

Slide 14

Slide 14 text

The warmup problem def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) } measure() measure() 26 ms, 11 ms

Slide 15

Slide 15 text

The warmup problem def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) } measure() measure() 26 ms, 11 ms Why? Mainly: - JIT compilation - dynamic optimization

Slide 16

Slide 16 text

The warmup problem def measure() { val buffer = mutable.ArrayBuffer(0 until 2000000: _*) val start = System.currentTimeMillis() var sum = 0 buffer.foreach(sum += _) val end = System.currentTimeMillis() println(end - start) } measure() measure() 45 ms, 10 ms 26 ms, 11 ms

Slide 17

Slide 17 text

The warmup problem def measure2() { val buffer = mutable.ArrayBuffer(0 until 4000000: _*) val start = System.currentTimeMillis() buffer.map(_ + 1) val end = System.currentTimeMillis() println(end - start) }

Slide 18

Slide 18 text

The warmup problem def measure2() { val buffer = mutable.ArrayBuffer(0 until 4000000: _*) val start = System.currentTimeMillis() buffer.map(_ + 1) val end = System.currentTimeMillis() println(end - start) } 241, 238, 235, 236, 234

Slide 19

Slide 19 text

The warmup problem def measure2() { val buffer = mutable.ArrayBuffer(0 until 4000000: _*) val start = System.currentTimeMillis() buffer.map(_ + 1) val end = System.currentTimeMillis() println(end - start) } 241, 238, 235, 236, 234, 429

Slide 20

Slide 20 text

The warmup problem def measure2() { val buffer = mutable.ArrayBuffer(0 until 4000000: _*) val start = System.currentTimeMillis() buffer.map(_ + 1) val end = System.currentTimeMillis() println(end - start) } 241, 238, 235, 236, 234, 429, 209

Slide 21

Slide 21 text

The warmup problem def measure2() { val buffer = mutable.ArrayBuffer(0 until 4000000: _*) val start = System.currentTimeMillis() buffer.map(_ + 1) val end = System.currentTimeMillis() println(end - start) } 241, 238, 235, 236, 234, 429, 209, 194, 195, 195

Slide 22

Slide 22 text

The warmup problem Bottomline: benchmark has to be repeated until the running time becomes “stable”. The number of repetitions is not known in advance. 241, 238, 235, 236, 234, 429, 209, 194, 195, 195

Slide 23

Slide 23 text

Warming up the JVM 241, 238, 235, 236, 234, 429, 209, 194, 195, 195, 194, 194, 193, 194, 196, 195, 195

Slide 24

Slide 24 text

Warming up the JVM 241, 238, 235, 236, 234, 429, 209, 194, 195, 195, 194, 194, 193, 194, 196, 195, 195

Slide 25

Slide 25 text

The interference problem val buffer = ArrayBuffer(0 until 900000: _*) buffer.map(_ + 1) val buffer = ListBuffer(0 until 900000: _*) buffer.map(_ + 1)

Slide 26

Slide 26 text

The interference problem Lets measure the first map 3 times with 7 repetitions: val buffer = ArrayBuffer(0 until 900000: _*) buffer.map(_ + 1) val buffer = ListBuffer(0 until 900000: _*) buffer.map(_ + 1) 61, 54, 54, 54, 55, 55, 56 186, 54, 54, 54, 55, 54, 53 54, 54, 53, 53, 53, 54, 51

Slide 27

Slide 27 text

The interference problem val buffer = ArrayBuffer(0 until 900000: _*) buffer.map(_ + 1) val buffer = ListBuffer(0 until 900000: _*) buffer.map(_ + 1) Now, lets measure the list buffer map in between: 61, 54, 54, 54, 55, 55, 56 186, 54, 54, 54, 55, 54, 53 54, 54, 53, 53, 53, 54, 51 59, 54, 54, 54, 54, 54, 54 44, 36, 36, 36, 35, 36, 36 45, 45, 45, 45, 44, 46, 45 18, 17, 18, 18, 17, 292, 16 45, 45, 44, 44, 45, 45, 44

Slide 28

Slide 28 text

The interference problem val buffer = ArrayBuffer(0 until 900000: _*) buffer.map(_ + 1) val buffer = ListBuffer(0 until 900000: _*) buffer.map(_ + 1) Now, lets measure the list buffer map in between: 61, 54, 54, 54, 55, 55, 56 186, 54, 54, 54, 55, 54, 53 54, 54, 53, 53, 53, 54, 51 59, 54, 54, 54, 54, 54, 54 44, 36, 36, 36, 35, 36, 36 45, 45, 45, 45, 44, 46, 45 18, 17, 18, 18, 17, 292, 16 45, 45, 44, 44, 45, 45, 44

Slide 29

Slide 29 text

Using separate JVM Bottomline: always run the tests in a new JVM.

Slide 30

Slide 30 text

Using separate JVM Bottomline: always run the tests in a new JVM. This may not reflect a real-world scenario, but it gives a good idea of how different several alternatives are.

Slide 31

Slide 31 text

Using separate JVM Bottomline: always run the tests in a new JVM. It results in a reproducible, more stable measurement.

Slide 32

Slide 32 text

The List.map example val list = (0 until 2500000).toList list.map(_ % 2 == 0)

Slide 33

Slide 33 text

The List.map example val list = (0 until 2500000).toList list.map(_ % 2 == 0) 37, 38, 37, 1175, 38, 37, 37, 37, 37, …, 38, 37, 37, 37, 37, 465, 35, 35, …

Slide 34

Slide 34 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) 37, 38, 37, 1175, 38, 37, 37, 37, 37, …, 38, 37, 37, 37, 37, 465, 35, 35, … This benchmark triggers GC cycles!

Slide 35

Slide 35 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) 37, 38, 37, 1175, 38, 37, 37, 37, 37, …, 38, 37, 37, 37, 37, 465, 35, 35, … -> mean: 47 ms This benchmark triggers GC cycles!

Slide 36

Slide 36 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) 37, 38, 37, 1175, 38, 37, 37, 37, 37, …, 38, 37, 37, 37, 37, 465, 35, 35, … -> mean: 47 ms This benchmark triggers GC cycles! 37, 37, 37, 647, 37, 36, 38, 37, 36, …, 36, 37, 36, 37, 36, 37, 534, 36, 33, … -> mean: 39 ms

Slide 37

Slide 37 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) Solutions: - repeat A LOT of times –an accurate mean, but takes A LONG time

Slide 38

Slide 38 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) Solutions: - repeat A LOT of times –an accurate mean, but takes A LONG time - ignore the measurements with GC – gives a reproducible value, and less measurements

Slide 39

Slide 39 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) Solutions: - repeat A LOT of times –an accurate mean, but takes A LONG time - ignore the measurements with GC – gives a reproducible value, and less measurements - how to do this?

Slide 40

Slide 40 text

The garbage collection problem val list = (0 until 2500000).toList list.map(_ % 2 == 0) - manually - verbose:gc

Slide 41

Slide 41 text

Automatic GC detection val list = (0 until 2500000).toList list.map(_ % 2 == 0) - manually - verbose:gc - automatically using callbacks in JDK7 37, 37, 37, 647, 37, 36, 38, 37, 36, …, 36, 37, 36, 37, 36, 37, 534, 36, 33, …

Slide 42

Slide 42 text

Automatic GC detection val list = (0 until 2500000).toList list.map(_ % 2 == 0) - manually - verbose:gc - automatically using callbacks in JDK7 37, 37, 37, 647, 37, 36, 38, 37, 36, …, 36, 37, 36, 37, 36, 37, 534, 36, 33, … raises a GC event

Slide 43

Slide 43 text

The runtime problem - there are other runtime events beside GC – e.g. JIT compilation, dynamic optimization, etc. - these take time, but cannot be determined accurately

Slide 44

Slide 44 text

The runtime problem - there are other runtime events beside GC – e.g. JIT compilation, dynamic optimization, etc. - these take time, but cannot be determined accurately - heap state also influences memory allocation patterns and performance

Slide 45

Slide 45 text

The runtime problem - there are other runtime events beside GC – e.g. JIT compilation, dynamic optimization, etc. - these take time, but cannot be determined accurately - heap state also influences memory allocation patterns and performance val list = (0 until 4000000).toList list.groupBy(_ % 10) (allocation intensive)

Slide 46

Slide 46 text

The runtime problem - there are other runtime events beside GC – e.g. JIT compilation, dynamic optimization, etc. - these take time, but cannot be determined accurately - heap state also influences memory allocation patterns and performance val list = (0 until 4000000).toList list.groupBy(_ % 10) 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110

Slide 47

Slide 47 text

The runtime problem - there are other runtime events beside GC – e.g. JIT compilation, dynamic optimization, etc. - these take time, but cannot be determined accurately - heap state also influences memory allocation patterns and performance val list = (0 until 4000000).toList list.groupBy(_ % 10) 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110 affects the mean – 116 ms vs 178 ms

Slide 48

Slide 48 text

Outlier elimination 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110

Slide 49

Slide 49 text

Outlier elimination 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110 109, 110, 111, 113, 115, 118, 120, 121, 122, 123, 794 sort

Slide 50

Slide 50 text

Outlier elimination 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110 109, 110, 111, 113, 115, 118, 120, 121, 122, 123, 794 sort inspect tail and its variance contribution 109, 110, 111, 113, 115, 118, 120, 121, 122, 123

Slide 51

Slide 51 text

Outlier elimination 120, 121, 122, 118, 123, 794, 109, 111, 115, 113, 110 109, 110, 111, 113, 115, 118, 120, 121, 122, 123, 794 sort inspect tail and its variance contribution 109, 110, 111, 113, 115, 118, 120, 121, 122, 123 109, 110, 111, 113, 115, 118, 120, 121, 122, 123, 124 redo the measurement

Slide 52

Slide 52 text

ScalaMeter Test info

Slide 53

Slide 53 text

ScalaMeter Test info Scala test Java test

Slide 54

Slide 54 text

ScalaMeter Test info Executor Scala test Java test

Slide 55

Slide 55 text

ScalaMeter Test info Executor Scala test Java test Warmer Measurer

Slide 56

Slide 56 text

ScalaMeter Test info Executor Scala test Java test Warmer Measurer Memory

Slide 57

Slide 57 text

ScalaMeter Test info Executor Scala test Java test Warmer Measurer Memory Duration

Slide 58

Slide 58 text

ScalaMeter Test info Executor Scala test Java test Warmer Measurer Memory Duration # GC

Slide 59

Slide 59 text

ScalaMeter Test info Executor Scala test Java test Warmer Measurer Memory Duration # GC (box count)

Slide 60

Slide 60 text

ScalaMeter Test info Executor Scala test Java test New VM Local Warmer Measurer

Slide 61

Slide 61 text

ScalaMeter Test info Executor Reporter(s) Scala test Java test New VM Local Warmer Measurer

Slide 62

Slide 62 text

ScalaMeter Test info Executor Reporter(s) Scala test Java test New VM Local Logging Chart HTML Warmer Measurer

Slide 63

Slide 63 text

ScalaMeter Test info Executor Reporter(s) Scala test Java test New VM Local Logging Chart HTML Warmer Measurer Regression Historian Tester Persistor

Slide 64

Slide 64 text

ScalaMeter example object ListTest extends PerformanceTest.Microbenchmark { A range of predefined benchmark types Scala test

Slide 65

Slide 65 text

ScalaMeter example object ListTest extends PerformanceTest.Microbenchmark { val sizes = Gen.range("size”)(500000, 1000000, 100000) Generators provide input data for tests Scala test Generator(s)

Slide 66

Slide 66 text

ScalaMeter example object ListTest extends PerformanceTest.Microbenchmark { val sizes = Gen.range("size”)(500000, 1000000, 100000) val lists = for (sz <- sizes) yield (0 until sz).toList Generators can be composed a la ScalaCheck Scala test Generator(s)

Slide 67

Slide 67 text

ScalaMeter example object ListTest extends PerformanceTest.Microbenchmark { val sizes = Gen.range("size”)(500000, 1000000, 100000) val lists = for (sz <- sizes) yield (0 until sz).toList using(lists) in { xs => xs.groupBy(_ % 10) } } Concise syntax to specify and group tests Scala test Generator(s) Snippet(s)

Slide 68

Slide 68 text

ScalaMeter example object ListTest extends PerformanceTest.Microbenchmark { val sizes = Gen.range("size”)(500000, 1000000, 100000) val lists = for (sz <- sizes) yield (0 until sz).toList measure method “groupBy” in { using(lists) in { xs => xs.groupBy(_ % 10) } using(ranges) in { xs => xs.groupBy(_ % 10) } } }

Slide 69

Slide 69 text

Automatic regression testing using(lists) in { xs => var sum = 0 xs.foreach(x => sum += x) } Regression Historian Tester Persistor

Slide 70

Slide 70 text

Automatic regression testing using(lists) in { xs => var sum = 0 xs.foreach(x => sum += x) } [info] Test group: foreach [info] - foreach.Test-0 measurements: [info] - at size -> 2000000, 1 alternatives: passed [info] (ci = <7.28, 8.22>, significance = 1.0E-10) Regression Historian Tester Persistor

Slide 71

Slide 71 text

Automatic regression testing using(lists) in { xs => var sum = 0 xs.foreach(x => sum += math.sqrt(x)) } Regression Historian Tester Persistor

Slide 72

Slide 72 text

Automatic regression testing using(lists) in { xs => var sum = 0 xs.foreach(x => sum += math.sqrt(x)) } [info] Test group: foreach [info] - foreach.Test-0 measurements: [info] - at size -> 2000000, 2 alternatives: failed [info] (ci = <14.57, 15.38>, significance = 1.0E-10) [error] Failed confidence interval test: <-7.85, -6.60> [error] Previous (mean = 7.75, stdev = 0.44, ci = <7.28, 8.22>) [error] Latest (mean = 14.97, stdev = 0.38, ci = <14.57, 15.38>)

Slide 73

Slide 73 text

Automatic regression testing Regression Historian Tester Persistor

Slide 74

Slide 74 text

Report generation http://scala-blitz.github.io/home/documentation/benchmarks//chara.html

Slide 75

Slide 75 text

Online mode import org.scalameter._ val time = measure { for (i <- 0 until 100000) yield i } println(s"Total time: $time")

Slide 76

Slide 76 text

Online mode val time = config( Key.exec.benchRuns -> 20, Key.verbose -> true ) withWarmer { new Warmer.Default } withMeasurer { new Measurer.IgnoringGC } measure { for (i <- 0 until 100000) yield i } println(s"Total time: $time")

Slide 77

Slide 77 text

Tutorials online! http://scalameter.github.io Thank you!