Почему время выполнения независимых блоков кода зависит от порядка выполнения в Scala?

У меня есть программа, написанная на Scala. Я хотел измерить время выполнения разных независимых блоков кода. Когда я сделал это очевидным образом (то есть вставил System.nanoTime() до и после каждого блока), я заметил, что время выполнения зависит от порядка блоков. Первые одни блоки всегда занимали больше времени, чем другие.

Я создал минималистичный пример, воспроизводящий это поведение. Все блоки кода одинаковы и для простоты вызывают hashCode() для массива целых чисел.

package experiments

import scala.util.Random

/**
  * Measuring execution time of a code block
  *
  * Minimalistic example
  */
object CodeBlockMeasurement {

  def main(args: Array[String]): Unit = {
    val numRecords = args(0).toInt
    // number of independent measurements
    val iterations = args(1).toInt

    // Changes results a little bit, but not too much
    // val records2 = Array.fill[Int](1)(0)
    // records2.foreach(x => {})

    for (_ <- 1 to iterations) {
      measure(numRecords)
    }
  }

  def measure(numRecords: Int): Unit = {
    // using a new array every time
    val records = Array.fill[Int](numRecords)(new Random().nextInt())
    // block of code to be measured
    def doSomething(): Unit = {
      records.foreach(k => k.hashCode())
    }
    // measure execution time of the code-block
    elapsedTime(doSomething(), "HashCodeExperiment")
  }

  def elapsedTime(block: => Unit, name: String): Unit = {
    val t0 = System.nanoTime()
    val result = block
    val t1 = System.nanoTime()
    // print out elapsed time in milliseconds
    println(s"$name took ${(t1 - t0).toDouble / 1000000} ms")
  }
}

После запуска программы с numRecords = 100000 и iterations = 10 моя консоль выглядит так:

HashCodeExperiment занял 14,630283 мс
HashCodeExperiment занял 7,125693 мс
HashCodeExperiment занял 0,368151 мс
HashCodeExperiment занял 0,431628 мс
HashCodeExperiment занял 0,086455 мс
HashCodeExperiment занял 0,056458 мс
HashCodeExperiment
HashCodeExperiment занял 0,055138 мс
заняло 0,062997 мс
HashCodeExperiment заняло 0,063736 мс
HashCodeExperiment заняло 0,056682 мс

Может кто-нибудь объяснить, почему это так? Разве все не должно быть одинаковым? Какое реальное время выполнения?

Большое спасибо,
Питер

Параметры среды:
ОС: ubuntu 14.04 LTS (64-разрядная версия)
IDE: IntelliJ IDEA 2016.1.1 (IU-145.597)
Scala: 2.11.7


person nemderogatorius    schedule 05.05.2016    source источник
comment
Надежно протестировать языки с GCed непросто - еще сложнее протестировать языки с GC и JIT. Я бы сказал, что то, что вы видите здесь на первых нескольких итерациях, - это среда выполнения JIT и JVM в действии.   -  person Patryk Ćwiek    schedule 05.05.2016


Ответы (2)


Срабатывает JIT Java. Сначала выполняется простой байт-код, но через некоторое время ( 1,5k / 10k вызовов по умолчанию для Oracle JVM, см. -XX:CompileThreshold) при оптимизации начинается обработка реального исполняемого нативного кода, что обычно приводит к значительному повышению производительности.

Как упоминает Иван, есть кеширование промежуточного байт-кода / нативного кода и различных других задействованных технологий, одной из наиболее важных из которых является сам сборщик мусора, который вызывает еще большую вариативность отдельных результатов. В зависимости от того, насколько сильно код выделяет новые объекты, это может полностью снизить производительность всякий раз, когда происходит сборщик мусора, но это отдельная проблема.

Чтобы удалить такие резко отклоняющиеся результаты при микробенчмаркинге, рекомендуется протестировать несколько итераций действия и отбросить нижние и верхние 5..10% результатов и выполнить оценку производительности на основе оставшихся выборок.

person Esko    schedule 05.05.2016

Краткий ответ: кеширование.

Это независимые блоки кода, но запуски не могут быть полностью независимыми, потому что они выполняются в одном экземпляре JVM и в одном процессе одного процессора. Сама JVM имеет много внутренней оптимизации, включая кеширование. Современные процессоры тоже так делают. Таким образом, это довольно распространенное поведение: повторный запуск обычно занимает меньше времени, чем первый запуск.

person Ivan Klass    schedule 05.05.2016