Bagaimana cara membuat profil metode di Scala?

Apa cara standar untuk membuat profil panggilan metode Scala?

Yang saya butuhkan adalah kait di sekitar metode, yang dapat digunakan untuk memulai dan menghentikan Timer.

Di Java saya menggunakan pemrograman aspek, aspekJ, untuk menentukan metode yang akan diprofilkan dan menyuntikkan bytecode untuk mencapai hal yang sama.

Apakah ada cara yang lebih alami di Scala, di mana saya dapat menentukan banyak fungsi yang akan dipanggil sebelum dan sesudah suatu fungsi tanpa kehilangan pengetikan statis apa pun dalam prosesnya?

Apakah Anda ingin melakukan ini tanpa mengubah kode yang ingin Anda ukur pengaturan waktunya? Jika Anda tidak keberatan mengubah kodenya, Anda dapat melakukan sesuatu seperti ini:

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 }

Selain jawaban Jesper, Anda dapat secara otomatis menggabungkan pemanggilan metode di 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

Sekarang - mari kita bungkus apa pun di sini

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

OK - kita harus dalam mode daya

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

Bungkus

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

Saya tidak tahu mengapa barang-barang itu dicetak 5 kali

Pembaruan pada 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

Ada tiga pustaka pembandingan untuk Scala yang dapat Anda manfaatkan.

Karena URL di situs tertaut cenderung berubah, saya menempelkan konten yang relevan di bawah ini.

1. SPerformance - Kerangka kerja Pengujian Kinerja yang bertujuan untuk membandingkan pengujian kinerja secara otomatis dan bekerja di dalam Simple Build Tool.

2. scala-benchmarking-template - Proyek template SBT untuk membuat benchmark Scala (mikro-) berdasarkan Caliper.

3. Metrik - Menangkap JVM- dan metrik tingkat aplikasi. Jadi Anda tahu apa yang sedang terjadi

Ini yang saya gunakan:

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 semoga bermanfaat.

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

Saya mengambil solusi dari Jesper dan menambahkan beberapa agregasi padanya di beberapa menjalankan kode yang sama

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

Misalkan Anda ingin mengatur waktu dua fungsi counter_newdan counter_old, berikut ini adalah penggunaan:

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

Semoga bermanfaat

Saya menggunakan teknik yang mudah dipindahkan dalam blok kode. Intinya adalah baris yang sama persis memulai dan mengakhiri pengatur waktu - jadi ini benar-benar merupakan salin dan tempel sederhana. Hal baik lainnya adalah Anda bisa mendefinisikan apa arti timing bagi Anda sebagai string, semuanya dalam baris yang sama.

Contoh penggunaan:

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

Kode:

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

Kelebihan:

• tidak perlu membungkus kode sebagai blok atau memanipulasi dalam baris
• dapat dengan mudah memindahkan awal dan akhir pengatur waktu di antara baris kode saat sedang eksplorasi

Kekurangan:

• kurang berkilau untuk kode yang sepenuhnya berfungsi
• jelas objek ini membocorkan entri peta jika Anda tidak "menutup" pengatur waktu, misalnya jika kode Anda tidak sampai ke pemanggilan kedua untuk awal pengatur waktu tertentu.

ScalaMeter adalah pustaka yang bagus untuk melakukan benchmarking di Scala

Di bawah ini adalah contoh sederhana

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

Jika Anda mengeksekusi potongan kode di atas dalam Scala Worksheet Anda mendapatkan waktu berjalan dalam milidetik

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

Saya suka kesederhanaan jawaban @ wrick, tetapi juga menginginkan:

• profiler menangani perulangan (untuk konsistensi dan kenyamanan)

• pengaturan waktu yang lebih akurat (menggunakan nanoTime)

• waktu per iterasi (bukan total waktu dari semua iterasi)

• hanya mengembalikan ns / iterasi - bukan tupel

Ini dicapai di sini:

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

Untuk akurasi yang lebih tinggi, modifikasi sederhana memungkinkan loop pemanasan Hotspot JVM (bukan waktunya) untuk mengatur waktu cuplikan kecil:

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
}

Pendekatan yang direkomendasikan untuk membandingan kode Scala adalah melalui sbt-jmh

"Jangan percaya siapa pun, taruh segalanya." - plugin sbt untuk JMH (Java Microbenchmark Harness)

Pendekatan ini diambil oleh banyak proyek Scala besar, misalnya,

• Bahasa pemrograman Scala itu sendiri
• Dotty (Scala 3)
• perpustakaan kucing untuk pemrograman fungsional
• Server bahasa logam untuk IDE

Sederhana wrapper waktu berdasarkan System.nanoTimeadalah tidak metode yang dapat diandalkan dari pembandingan:

System.nanoTimeseburuk String.internsekarang: Anda bisa menggunakannya, tapi gunakan dengan bijak. Efek latensi, perincian, dan skalabilitas yang diperkenalkan oleh pengatur waktu dapat dan akan memengaruhi pengukuran Anda jika dilakukan tanpa ketelitian yang tepat. Ini adalah salah satu dari banyak alasan mengapa System.nanoTimeharus disarikan dari pengguna dengan kerangka kerja benchmark

Selain itu, pertimbangan seperti pemanasan JIT , pengumpulan sampah, peristiwa di seluruh sistem, dll. Mungkin menyebabkan ketidakpastian dalam pengukuran:

Banyak efek perlu dikurangi, termasuk pemanasan, penghapusan kode mati, forking, dll. Untungnya, JMH sudah menangani banyak hal, dan memiliki binding untuk Java dan Scala.

Berdasarkan jawaban Travis Brown berikut adalah contoh bagaimana mengatur benchmark JMH untuk Scala

1. Tambahkan jmh ke project/plugins.sbt

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

2. Aktifkan plugin jmh di build.sbt

   enablePlugins(JmhPlugin)

3. Tambahkan 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. Jalankan benchmark dengan

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

Hasilnya adalah

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

yang tampaknya menunjukkan prepending ke a Listdan kemudian membalikkannya pada akhirnya adalah urutan besarnya lebih cepat daripada terus menambahkan ke a Vector.

Sambil berdiri di pundak raksasa ...

Pustaka pihak ketiga yang solid akan lebih ideal, tetapi jika Anda membutuhkan sesuatu yang cepat dan berbasis pustaka std, varian berikut menyediakan:

• Pengulangan
• Hasil terakhir menang untuk beberapa pengulangan
• Total waktu dan waktu rata-rata untuk beberapa pengulangan
• Menghilangkan kebutuhan akan waktu / penyedia instan sebagai param

.

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

Juga perlu diperhatikan Anda dapat menggunakan Duration.toCoarsestmetode untuk mengonversi ke satuan waktu terbesar, meskipun saya tidak yakin seberapa ramah ini dengan perbedaan waktu kecil antara berjalan misalnya

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> 

Kamu bisa memakai 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
}

Pemakaian:

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

nanoTime akan menunjukkannya kepada Anda ns, sehingga akan sulit dilihat. Jadi saya menyarankan agar Anda dapat menggunakan currentTimeMillis sebagai gantinya.