Как профилировать методы в Scala?
Каков стандартный способ профилирования вызовов методов Scala?
Что мне нужно, так это использовать метод, с помощью которого я могу запускать и останавливать таймеры.
В Java я использую аспектное программирование aspectJ, чтобы определить профилируемые методы и внедрить байт-код для достижения того же самого.
Есть ли более естественный способ в Scala, где я могу определить набор функций для вызова до и после функции, не теряя при этом статической типизации в процессе?
13 ответов
Вы хотите сделать это без изменения кода, для которого вы хотите измерить время? Если вы не против изменить код, то вы можете сделать что-то вроде этого:
def time[R](block: => R): R = {
val t0 = System.nanoTime()
val result = block // call-by-name
val t1 = System.nanoTime()
println("Elapsed time: " + (t1 - t0) + "ns")
result
}
// Now wrap your method calls, for example change this...
val result = 1 to 1000 sum
// ... into this
val result = time { 1 to 1000 sum }
В дополнение к ответу Джеспера вы можете автоматически переносить вызовы методов в REPL:
scala> def time[R](block: => R): R = {
| val t0 = System.nanoTime()
| val result = block
| println("Elapsed time: " + (System.nanoTime - t0) + "ns")
| result
| }
time: [R](block: => R)R
Теперь - давайте завернем что-нибудь в это
scala> :wrap time
wrap: no such command. Type :help for help.
ОК - мы должны быть в режиме питания
scala> :power
** Power User mode enabled - BEEP BOOP SPIZ **
** :phase has been set to 'typer'. **
** scala.tools.nsc._ has been imported **
** global._ and definitions._ also imported **
** Try :help, vals.<tab>, power.<tab> **
Обернуть
scala> :wrap time
Set wrapper to 'time'
scala> BigDecimal("1.456")
Elapsed time: 950874ns
Elapsed time: 870589ns
Elapsed time: 902654ns
Elapsed time: 898372ns
Elapsed time: 1690250ns
res0: scala.math.BigDecimal = 1.456
Я понятия не имею, почему это напечатано 5 раз
Обновление от 2.12.2:
scala> :pa
// Entering paste mode (ctrl-D to finish)
package wrappers { object wrap { def apply[A](a: => A): A = { println("running...") ; a } }}
// Exiting paste mode, now interpreting.
scala> $intp.setExecutionWrapper("wrappers.wrap")
scala> 42
running...
res2: Int = 42
Это то, что я использую:
import System.nanoTime
def profile[R](code: => R, t: Long = nanoTime) = (code, nanoTime - t)
// usage:
val (result, time) = profile {
/* block of code to be profiled*/
}
val (result2, time2) = profile methodToBeProfiled(foo)
Есть три библиотеки для Scala, которые вы можете использовать.
Поскольку URL на связанном сайте могут измениться, я добавляю соответствующий контент ниже.
SPerformance - платформа Performance Testing, предназначенная для автоматического сравнения тестов производительности и работы внутри Simple Build Tool.
https://github.com/sirthias/scala-benchmarking-template - шаблонный проект SBT для создания (микро) тестов Scala на основе Caliper.
Метрики - сбор метрик JVM и приложений. Итак, вы знаете, что происходит
Я использую технику, которую легко перемещать в блоках кода. Суть в том, что одна и та же строка запускает и заканчивает таймер - так что это действительно простое копирование и вставка. Еще одна приятная вещь заключается в том, что вы можете определить, что время означает для вас как строка, все в той же строке.
Пример использования:
Timelog("timer name/description")
//code to time
Timelog("timer name/description")
Код:
object Timelog {
val timers = scala.collection.mutable.Map.empty[String, Long]
//
// Usage: call once to start the timer, and once to stop it, using the same timer name parameter
//
def timer(timerName:String) = {
if (timers contains timerName) {
val output = s"$timerName took ${(System.nanoTime() - timers(timerName)) / 1000 / 1000} milliseconds"
println(output) // or log, or send off to some performance db for analytics
}
else timers(timerName) = System.nanoTime()
}
Плюсы:
- не нужно оборачивать код как блок или манипулировать внутри строк
- может легко перемещать начало и конец таймера между строками кода при поиске
Минусы:
- менее блестящий для полностью функционального кода
- очевидно, этот объект пропускает записи карты, если вы не "закрываете" таймеры, например, если ваш код не попадает во второй вызов для данного запуска таймера.
testing.Benchmark может быть полезным.
scala> def testMethod {Thread.sleep(100)}
testMethod: Unit
scala> object Test extends testing.Benchmark {
| def run = testMethod
| }
defined module Test
scala> Test.main(Array("5"))
$line16.$read$$iw$$iw$Test$ 100 100 100 100 100
Рекомендуемый подход к тестированию кода Scala - через sbt-jmh.
"Никому не верь, все жди". - плагин sbt для JMH (Java Microbenchmark Harness)
Этот подход используется во многих крупных проектах Scala, например,
- Сам язык программирования Scala
- Дотти (Scala 3)
- библиотека кошек для функционального программирования
- Языковой сервер Metals для IDE
Простой таймер оболочки на основе System.nanoTimeэто не надежный метод бенчмаркинга:
System.nanoTimeтак же плохо, какString.internсейчас: вы можете использовать его, но используйте его с умом. Эффекты задержки, гранулярности и масштабируемости, вносимые таймерами, могут и будут влиять на ваши измерения, если они будут выполнены без должной строгости. Это одна из многих причин, почемуSystem.nanoTimeследует абстрагироваться от пользователей с помощью фреймворков для тестирования
Кроме того, такие соображения, как JIT-разогрев, сборка мусора, общесистемные события и т. Д., Могут внести непредсказуемость в измерения:
Необходимо смягчить тонны эффектов, включая разогрев, удаление мертвого кода, разветвление и т. Д. К счастью, JMH уже позаботился о многих вещах и имеет привязки как для Java, так и для Scala.
Основываясь на ответе Трэвиса Брауна, вот пример того, как настроить тест JMH для Scala.
- Добавить jmh в
project/plugins.sbtaddSbtPlugin("pl.project13.scala" % "sbt-jmh" % "0.3.7") - Включить плагин jmh в
build.sbtenablePlugins(JmhPlugin) добавить в
src/main/scala/bench/VectorAppendVsListPreppendAndReverse.scalapackage bench import org.openjdk.jmh.annotations._ @State(Scope.Benchmark) @BenchmarkMode(Array(Mode.AverageTime)) class VectorAppendVsListPreppendAndReverse { val size = 1_000_000 val input = 1 to size @Benchmark def vectorAppend: Vector[Int] = input.foldLeft(Vector.empty[Int])({ case (acc, next) => acc.appended(next)}) @Benchmark def listPrependAndReverse: List[Int] = input.foldLeft(List.empty[Int])({ case (acc, next) => acc.prepended(next)}).reverse }- Выполнить тест с
sbt "jmh:run -i 10 -wi 10 -f 2 -t 1 bench.VectorAppendVsListPreppendAndReverse"
Результаты
Benchmark Mode Cnt Score Error Units
VectorAppendVsListPreppendAndReverse.listPrependAndReverse avgt 20 0.024 ± 0.001 s/op
VectorAppendVsListPreppendAndReverse.vectorAppend avgt 20 0.130 ± 0.003 s/op
что, кажется, указывает на добавление к List а затем перевернуть его в конце на порядок быстрее, чем продолжать добавлять к Vector.
ScalaMeter - это хорошая библиотека для тестирования производительности в Scala
Ниже приведен простой пример
import org.scalameter._
def sumSegment(i: Long, j: Long): Long = (i to j) sum
val (a, b) = (1, 1000000000)
val execution_time = measure { sumSegment(a, b) }
Если вы выполните приведенный выше фрагмент кода в Scala Worksheet, вы получите время выполнения в миллисекундах.
execution_time: org.scalameter.Quantity[Double] = 0.260325 ms
Я взял решение от Jesper и добавил к нему несколько агрегаций при многократном запуске одного и того же кода
def time[R](block: => R) = {
def print_result(s: String, ns: Long) = {
val formatter = java.text.NumberFormat.getIntegerInstance
println("%-16s".format(s) + formatter.format(ns) + " ns")
}
var t0 = System.nanoTime()
var result = block // call-by-name
var t1 = System.nanoTime()
print_result("First Run", (t1 - t0))
var lst = for (i <- 1 to 10) yield {
t0 = System.nanoTime()
result = block // call-by-name
t1 = System.nanoTime()
print_result("Run #" + i, (t1 - t0))
(t1 - t0).toLong
}
print_result("Max", lst.max)
print_result("Min", lst.min)
print_result("Avg", (lst.sum / lst.length))
}
Предположим, вы хотите рассчитать две функции counter_new а также counter_old, следующее использование:
scala> time {counter_new(lst)}
First Run 2,963,261,456 ns
Run #1 1,486,928,576 ns
Run #2 1,321,499,030 ns
Run #3 1,461,277,950 ns
Run #4 1,299,298,316 ns
Run #5 1,459,163,587 ns
Run #6 1,318,305,378 ns
Run #7 1,473,063,405 ns
Run #8 1,482,330,042 ns
Run #9 1,318,320,459 ns
Run #10 1,453,722,468 ns
Max 1,486,928,576 ns
Min 1,299,298,316 ns
Avg 1,407,390,921 ns
scala> time {counter_old(lst)}
First Run 444,795,051 ns
Run #1 1,455,528,106 ns
Run #2 586,305,699 ns
Run #3 2,085,802,554 ns
Run #4 579,028,408 ns
Run #5 582,701,806 ns
Run #6 403,933,518 ns
Run #7 562,429,973 ns
Run #8 572,927,876 ns
Run #9 570,280,691 ns
Run #10 580,869,246 ns
Max 2,085,802,554 ns
Min 403,933,518 ns
Avg 797,980,787 ns
Надеюсь, это полезно
Мне нравится простота ответа @wrick, но я также хотел:
профилировщик обрабатывает циклы (для согласованности и удобства)
более точные сроки (используя nanoTime)
время на итерацию (не общее время всех итераций)
просто верните ns/ итерацию - не кортеж
Это достигается здесь:
def profile[R] (repeat :Int)(code: => R, t: Long = System.nanoTime) = {
(1 to repeat).foreach(i => code)
(System.nanoTime - t)/repeat
}
Для еще большей точности простая модификация позволяет циклу разогрева горячей точки JVM (не синхронизирован) для синхронизации небольших фрагментов:
def profile[R] (repeat :Int)(code: => R) = {
(1 to 10000).foreach(i => code) // warmup
val start = System.nanoTime
(1 to repeat).foreach(i => code)
(System.nanoTime - start)/repeat
}
Ты можешь использовать System.currentTimeMillis:
def time[R](block: => R): R = {
val t0 = System.currentTimeMillis()
val result = block // call-by-name
val t1 = System.currentTimeMillis()
println("Elapsed time: " + (t1 - t0) + "ms")
result
}
Использование:
time{
//execute somethings here, like methods, or some codes.
}
nanoTime покажет вам nsТак что это будет трудно увидеть. Поэтому я предлагаю вам использовать currentTimeMillis вместо него.
Стоя на плечах великанов...
Надежная сторонняя библиотека была бы более идеальной, но если вам нужно что-то быстрое и основанное на std-библиотеках, следующий вариант обеспечивает:
- Повторы
- Последний результат выигрывает за несколько повторений
- Общее время и среднее время для нескольких повторений
- Устраняет необходимость времени / мгновенного провайдера в качестве параметра
,
import scala.concurrent.duration._
import scala.language.{postfixOps, implicitConversions}
package object profile {
def profile[R](code: => R): R = profileR(1)(code)
def profileR[R](repeat: Int)(code: => R): R = {
require(repeat > 0, "Profile: at least 1 repetition required")
val start = Deadline.now
val result = (1 until repeat).foldLeft(code) { (_: R, _: Int) => code }
val end = Deadline.now
val elapsed = ((end - start) / repeat)
if (repeat > 1) {
println(s"Elapsed time: $elapsed averaged over $repeat repetitions; Total elapsed time")
val totalElapsed = (end - start)
println(s"Total elapsed time: $totalElapsed")
}
else println(s"Elapsed time: $elapsed")
result
}
}
Также стоит отметить, что вы можете использовать Duration.toCoarsest метод преобразования в максимально возможную единицу времени, хотя я не уверен, насколько это удобно с небольшой разницей во времени между запусками, например
Welcome to Scala version 2.11.7 (Java HotSpot(TM) 64-Bit Server VM, Java 1.8.0_60).
Type in expressions to have them evaluated.
Type :help for more information.
scala> import scala.concurrent.duration._
import scala.concurrent.duration._
scala> import scala.language.{postfixOps, implicitConversions}
import scala.language.{postfixOps, implicitConversions}
scala> 1000.millis
res0: scala.concurrent.duration.FiniteDuration = 1000 milliseconds
scala> 1000.millis.toCoarsest
res1: scala.concurrent.duration.Duration = 1 second
scala> 1001.millis.toCoarsest
res2: scala.concurrent.duration.Duration = 1001 milliseconds
scala>
добавление on => метода с именем и секундами
profile[R](block: => R,methodName : String): R = {
val n = System.nanoTime()
val result = block
val n1 = System.nanoTime()
println(s"Elapsed time: ${TimeUnit.MILLISECONDS.convert(n1 - n,TimeUnit.NANOSECONDS)}ms - MethodName: ${methodName}")
result
}