Jak profilować metody w Scali?

117

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?

sheki
źródło
Jeśli AspectJ ładnie współgra ze Scalą, użyj AspectJ. Po co odkrywać koło na nowo? Powyższe odpowiedzi, które używają niestandardowej kontroli przepływu, nie spełniają podstawowych wymagań AOP, ponieważ aby ich użyć, musisz zmodyfikować kod. Te również mogą być interesujące: java.dzone.com/articles/real-world-scala-managing-cros blog.fakod.eu/2010/07/26/cross-cutting-concerns-in-scala
Ant Kutschera
Czym się interesujesz? Chcesz wiedzieć, ile czasu zajmuje dana metoda w środowisku produkcyjnym. Następnie powinieneś zajrzeć do bibliotek metryk i nie toczyć pomiarów samodzielnie, jak w zaakceptowanej odpowiedzi. Jeśli chcesz sprawdzić, który wariant kodu jest szybszy "ogólnie", tj. W twoim środowisku programistycznym, użyj sbt-jmh, jak pokazano poniżej.
jmg

Odpowiedzi:

214

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 }
Jesper
źródło
To jest fajne, czy mogę zrobić to samo bez zmiany kodu?
sheki
Nie automatycznie w przypadku tego rozwiązania; skąd Scala miałaby wiedzieć, na co chcesz mieć czas?
Jesper
1
To nie jest do końca prawda - możesz automatycznie zawijać rzeczy w REPL
oxbow_lakes
1
Prawie idealne, ale musisz też reagować na możliwe wyjątki. Oblicz t1w ramach finallyklauzuli
juanmirocks
2
Możesz dodać etykietę do swoich wydruków z def time[R](label: String)(block: => R): R = {println
odrobiną curry
34

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
oxbow_lakes
źródło
8
Aby zaoszczędzić każdemu kłopotu z zastanawianiem się teraz, :wrapfunkcja została usunięta z REPL: - \
ches
25

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

missingfaktor
źródło
21

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)
pathikrit
źródło
6

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
Luigi Plinge
źródło
5
Należy pamiętać, że testing.Benchmark jest @deprecated ("Ta klasa zostanie usunięta.", "2.10.0").
Tvaroh
5

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

John Zhu
źródło
4

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.
matanster
źródło
To jest dobre, ale nie powinno być wykorzystanie: Timelog.timer("timer name/description")?
szkun
4

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
Dharmesz
źródło
3

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
}
Brent Faust
źródło
To nie jest odpowiedź, najlepiej byłoby napisać to jako komentarz
nedim
1
@nedim Rozwiązaniem jest pytanie - opakowanie na wszystko, co chcesz. Wszelkie funkcje, które OP chciałby wywołać, można umieścić w opakowaniu lub w bloku wywołującym jego funkcje, aby mógł on "zdefiniować zestaw funkcji, które mają być wywoływane przed i po funkcji bez utraty statycznego wpisywania"
Brent Faust
1
Masz rację. Przepraszam, musiałem przeoczyć kod. Po sprawdzeniu mojej zmiany mogę cofnąć głos przeciw.
nedim
3

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.

Mario Galic
źródło
1

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> 
Darren Bishop
źródło
1

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.

haiyang
źródło
Trudno dostrzec nanosekundy to kiepski powód do wybierania między nimi. Oprócz rozdzielczości jest kilka ważnych różnic. Po pierwsze, currentTimeMillis może zmieniać, a nawet cofać się podczas regulacji zegara, które system operacyjny wykonuje okresowo. Innym jest to, że nanoTime może nie być bezpieczny dla wątków: stackoverflow.com/questions/351565/…
Chris