Jak profilować metody w Scali?

Jaki jest standardowy sposób profilowania wywołań metod Scala?

To, czego potrzebuję, to haczyki wokół metody, za pomocą których mogę uruchamiać i zatrzymywać Timery.

W Javie używam programowania aspektowego, aspektuJ, do definiowania metod, które mają być profilowane i wstrzykiwania kodu bajtowego, aby osiągnąć to samo.

Czy istnieje bardziej naturalny sposób w Scali, w którym mogę zdefiniować kilka funkcji, które mają być wywoływane przed i po funkcji bez utraty statycznego wpisywania w procesie?

Czy chcesz to zrobić bez zmiany kodu, dla którego chcesz mierzyć czasy? Jeśli nie masz nic przeciwko zmianie kodu, możesz zrobić coś takiego:

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 }

Oprócz odpowiedzi Jespera możesz automatycznie zawijać wywołania metod w 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

Teraz - zawińmy w to wszystko

scala> :wrap time
wrap: no such command.  Type :help for help.

OK - musimy być w trybie zasilania

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>    **

Zawiń

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

Nie mam pojęcia, dlaczego te wydrukowane rzeczy wyszły 5 razy

Aktualizacja od 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

Istnieją trzy biblioteki testów porównawczych dla Scala , z których możesz skorzystać.

Ponieważ adresy URL w połączonej witrynie prawdopodobnie się zmienią, wklejam poniżej odpowiednią zawartość.

1. SPerformance - platforma do testowania wydajności, której celem jest automagiczne porównywanie testów wydajnościowych i praca w ramach narzędzia Simple Build Tool.

2. scala-benchmarking-template - projekt szablonu SBT do tworzenia (mikro) benchmarków Scala w oparciu o Caliper.

3. Metryki - przechwytywanie wskaźników JVM i poziomu aplikacji. Więc wiesz, co się dzieje

Tego używam:

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)

testing.Benchmark może się przydać.

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

Wziąłem rozwiązanie od Jespera i dodałem do niego trochę agregacji podczas wielokrotnych uruchomień tego samego kodu

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))
}

Załóżmy, że chcemy czasie dwie funkcje counter_newi counter_olddodaje jest użycie:

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

Mam nadzieję, że jest to pomocne

Używam techniki, którą łatwo poruszać się po blokach kodu. Sedno polega na tym, że ta sama dokładna linia zaczyna i kończy licznik czasu - więc jest to naprawdę proste kopiowanie i wklejanie. Inną fajną rzeczą jest to, że możesz zdefiniować, co oznacza dla ciebie timing jako ciąg, wszystko w tej samej linii.

Przykładowe użycie:

Timelog("timer name/description")
//code to time
Timelog("timer name/description")

Kod:

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()
  }

Plusy:

• nie ma potrzeby zawijania kodu jako bloku ani manipulowania w wierszach
• może łatwo przenosić początek i koniec licznika czasu między wierszami kodu podczas eksploracji

Cons:

• mniej błyszczące dla całkowicie funkcjonalnego kodu
• oczywiście ten obiekt przecieka wpisy mapy, jeśli nie "zamkniesz" timerów, np. jeśli twój kod nie dotrze do drugiego wywołania dla danego początku timera.

ScalaMeter to fajna biblioteka do wykonywania testów porównawczych w Scali

Poniżej znajduje się prosty przykład

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) }

Jeśli wykonasz powyższy fragment kodu w arkuszu Scala, uzyskasz czas działania w milisekundach

execution_time: org.scalameter.Quantity[Double] = 0.260325 ms

Podoba mi się prostota odpowiedzi @ wrick, ale chciałem też:

• profiler obsługuje zapętlenie (dla spójności i wygody)

• dokładniejszy czas (przy użyciu nanoTime)

• czas na iterację (nie całkowity czas wszystkich iteracji)

• po prostu zwróć ns / iterację - nie krotkę

Osiąga się to tutaj:

def profile[R] (repeat :Int)(code: => R, t: Long = System.nanoTime) = { 
  (1 to repeat).foreach(i => code)
  (System.nanoTime - t)/repeat
}

Aby uzyskać jeszcze większą dokładność, prosta modyfikacja umożliwia pętlę rozgrzewki JVM Hotspot (nieokreśloną w czasie) do synchronizowania małych fragmentów:

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
}

Zalecane podejście do testów porównawczych kodu Scala to sbt-jmh

„Nikomu nie ufaj, oceniaj wszystko”. - wtyczka sbt dla JMH (Java Microbenchmark Harness)

To podejście jest stosowane w wielu dużych projektach Scala, na przykład

• Sam język programowania Scala
• Dotty (Scala 3)
• biblioteka cats do programowania funkcjonalnego
• Serwer języka Metals dla IDE

Timer prosty wrapper na podstawie System.nanoTimeto nie jest wiarygodną metodą z benchmarkingu:

System.nanoTimejest tak samo zły jak String.internteraz: możesz go używać, ale używaj go mądrze. Efekty opóźnienia, ziarnistości i skalowalności wprowadzone przez timery mogą wpłynąć i wpłyną na pomiary, jeśli zostaną wykonane bez odpowiedniego rygoru. Jest to jeden z wielu powodów, dla których System.nanoTimenależy je oddzielić od użytkowników za pomocą frameworków porównawczych

Ponadto kwestie takie jak rozgrzewka JIT , zbieranie śmieci, zdarzenia w całym systemie itp. Mogą wprowadzać nieprzewidywalność do pomiarów:

Mnóstwo efektów należy złagodzić, w tym rozgrzewkę, eliminację martwego kodu, rozwidlenie itp. Na szczęście JMH zajmuje się już wieloma rzeczami i ma powiązania zarówno dla Javy, jak i Scali.

W oparciu o odpowiedź Travisa Browna, oto przykład konfiguracji JMH dla Scali

1. Dodaj jmh do project/plugins.sbt

   addSbtPlugin("pl.project13.scala" % "sbt-jmh" % "0.3.7")

2. Włącz wtyczkę jmh w build.sbt

   enablePlugins(JmhPlugin)

3. Dodać do src/main/scala/bench/VectorAppendVsListPreppendAndReverse.scala

   package 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
   }

4. Wykonaj test porównawczy z

   sbt "jmh:run -i 10 -wi 10 -f 2 -t 1 bench.VectorAppendVsListPreppendAndReverse"

Wyniki są

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

co wydaje się wskazywać na poprzedzanie a, Lista następnie odwrócenie go na końcu, jest o rząd wielkości szybsze niż ciągłe dołączanie do a Vector.

Stojąc na ramionach gigantów ...

Solidna biblioteka innej firmy byłaby bardziej idealna, ale jeśli potrzebujesz czegoś szybkiego i opartego na bibliotece standardowej, następujący wariant zapewnia:

• Powtórzenia
• Ostatni wynik wygrywa w przypadku wielu powtórzeń
• Całkowity czas i średni czas dla wielu powtórzeń
• Eliminuje potrzebę dostawcy czasu / natychmiastowego jako parametru

.

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
  }
}

Warto również zauważyć, że możesz użyć Duration.toCoarsestmetody konwersji na największą możliwą jednostkę czasu, chociaż nie jestem pewien, jak przyjazna jest to przy niewielkiej różnicy czasu między przebiegami, np.

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> 

Możesz użyć 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
}

Stosowanie:

time{
    //execute somethings here, like methods, or some codes.
}  

nanoTime pokaże ns, więc trudno będzie to zobaczyć. Sugeruję więc, aby zamiast tego użyć currentTimeMillis.