/* BSD 2-Clause License - see OPAL/LICENSE for details. */ package org.opalj package util import java.lang.management.ManagementFactory import scala.collection.mutable.Map import org.opalj.concurrent.Locking import org.opalj.log.OPALLogger import org.opalj.log.GlobalLogContext import org.opalj.log.LogContext /** * Measures the execution time of some code. * * ==Thread Safety== * This class is thread safe. * * @author Michael Eichberg */ class PerformanceEvaluation extends Locking { private[this] val timeSpans: Map[Symbol, Nanoseconds] = Map.empty /** * Times the execution of the given method / function literal / code block and * adds it to the execution time of previous methods / function literals / code blocks * that were measured and for which the same symbol was used.
* E.g., time('base_analysis){ ... do something ... } * * @param s Symbol used to put multiple measurements into relation. * @param f The function that will be evaluated and for which the execution * time will be measured. */ final def time[T](s: Symbol)(f: => T): T = { val startTime = System.nanoTime try { f } finally { val endTime = System.nanoTime val timeSpan = new Nanoseconds(endTime - startTime) withWriteLock { doUpdateTimes(s, timeSpan) } } } /** * Called by the `time` method. * * ==Thread Safety== * The `time` method takes care of the synchronization. */ protected[this] def doUpdateTimes(s: Symbol, timeSpan: Nanoseconds): Unit = { val oldTimeSpan = timeSpans.getOrElseUpdate(s, Nanoseconds.None) timeSpans.update(s, oldTimeSpan + timeSpan) } /** * Returns the overall time spent by computations with the given symbol. */ final def getTime(s: Symbol): Nanoseconds = withReadLock { doGetTime(s) } final def getNanoseconds(s: Symbol): Nanoseconds = getTime(s) final def getMilliseconds(s: Symbol): Milliseconds = getTime(s).toMilliseconds final def getSeconds(s: Symbol): Seconds = getTime(s).toSeconds /** * Called by the `getTime(Symbol)` method. * * ==Thread Safety== * The `getTime` method takes care of the synchronization. */ protected[this] def doGetTime(s: Symbol): Nanoseconds = { timeSpans.getOrElse(s, Nanoseconds.None) } /** * Resets the overall time spent by computations with the given symbol. */ def reset(s: Symbol): Unit = withWriteLock { doReset(s) } /** * Called by the `reset(Symbol)` method. * * ==Thread Safety== * The `reset` method takes care of the synchronization. */ private[this] def doReset(s: Symbol): Unit = timeSpans.remove(s) /** * Resets everything. The effect is comparable to creating a new * `PerformanceEvaluation` object, but is a bit more efficient. */ def resetAll(): Unit = withWriteLock { doResetAll() } /** * Called by the `resetAll` method. * * ==Thread Safety== * The `resetAll` method takes care of the synchronization. */ private[this] def doResetAll(): Unit = timeSpans.clear() } object GlobalPerformanceEvaluation extends PerformanceEvaluation /** * Collection of helper functions useful when evaluating the performance of some * code. * * @example * Measuring the time and memory used by some piece of code: * {{{ * import org.opalj.util.PerformanceEvaluation.{memory,time} * var store : Array[Object] = null * implicit val logContext = Some(org.opalj.log.GlobalLogContext) * for(i <- 1 to 5){ * memory{store = null}(l => println("empty: "+l)) * memory{ * time{ * store = Array.fill(1000000){val l : Object = List(i); l} * }(t => println("time:"+t.toSeconds)) * }(l => println("non-empty:"+l)) * } * }}} * * @author Michael Eichberg */ object PerformanceEvaluation { /** * Measures the amount of memory that is used as a side-effect * of executing the given function `f`. I.e., the amount of memory is measured that is * used before and after executing `f`; i.e., the permanent data structures that are created * by `f` are measured. * * @note If large data structures are used by `f` that are not used anymore afterwards * then it may happen that the used amount of memory is negative. */ def memory[T]( f: => T )( mu: Long => Unit )( implicit logContext: Option[LogContext] = None ): T = { val memoryMXBean = ManagementFactory.getMemoryMXBean gc(memoryMXBean) val usedBefore = memoryMXBean.getHeapMemoryUsage.getUsed val r = f gc(memoryMXBean) val usedAfter = memoryMXBean.getHeapMemoryUsage.getUsed mu(usedAfter - usedBefore) r } /** * Times the execution of a given function `f`. If the timing may be affected by * (required) garbage collection runs it is recommended to first run the garbage collector. * * @param r A function that is passed the time (in nanoseconds) that it * took to evaluate `f`. `r` is called even if `f` fails with an exception. */ def time[T](f: => T)(r: Nanoseconds => Unit): T = { val startTime: Long = System.nanoTime val result = try { f } finally { val endTime: Long = System.nanoTime r(Nanoseconds.TimeSpan(startTime, endTime)) } result } def timed[T](f: => T): (Nanoseconds, T) = { val startTime: Long = System.nanoTime val result = f (Nanoseconds.TimeSpan(startTime, System.nanoTime), result) } /** * Times the execution of a given function `f` until the execution time has * stabilized and the average time for evaluating `f` is only changing in a * well-understood manner. * * In general, `time` repeats the execution of `f` as long as the average changes * significantly. Furthermore, `f` is executed at least `minimalNumberOfRelevantRuns` * times and only those runs are taken into consideration for the calculation of the * average that are `consideredRunsEpsilon`% worse than the best run. However, if we * have more than `10*minimalNumberOfRelevantRuns` runs that did not contribute * to the calculation of the average, the last run is added anyway. This way, we * ensure that the evaluation will more likely terminate in reasonable time without * affecting the average too much. Nevertheless, if the behavior of `f` is * extremely erratic, the evaluation may not terminate. * * ==Example Usage== * {{{ * import org.opalj.util.PerformanceEvaluation._ * import org.opalj.util._ * time[String](2,4,3,{Thread.sleep(300).toString}){ (t, ts) => * val sTs = ts.map(t => f"\${t.toSeconds.timeSpan}%1.4f").mkString(", ") * println(f"Avg: \${avg(ts).timeSpan}%1.4f; T: \${t.toSeconds.timeSpan}%1.4f; Ts: \$sTs") * } * }}} * {{{ * import org.opalj.util.PerformanceEvaluation.{gc,memory,time,avg} * var store : Array[Object] = null * implicit val logContext = Some(org.opalj.log.GlobalLogContext) * time{ * for(i <- 1 to 5){ * memory{store = null}(l => println("empty: "+l)) * memory{ * time(2,4,3, * {store = Array.fill(1000000){val l : Object = List(i); l}}, * runGC=true * ){ (t, ts) => * val sTs = ts.map(t => f"\${t.toSeconds.timeSpan}%1.4f").mkString(", ") * println(f"Avg: \${avg(ts).timeSpan}%1.4f; T:\${t.toSeconds.timeSpan}%1.4f; Ts:\$sTs") * } * }(l => println("non-empty:"+l)) * } * }{t => println("overall-time:"+t.toSeconds)} * }}} * * @note **If `f` has side effects it may not be possible to use this method.** * * @note If epsilon is too small we can get an endless loop as the termination * condition is never met. However, in practice often a value such as "1 or 2" * is still useable. * * @note This method can generally only be used to measure the time of some process * that does not require user interaction or disk/network access. In the latter * case the variation between two runs will be too coarse grained to get * meaningful results. * * @param epsilon The maximum percentage that *the final run* is allowed to affect * the average. In other words, if the effect of the last execution on the * average is less than `epsilon` percent then the evaluation halts and the * result of the last run is returned. * @param consideredRunsEpsilon Controls which runs are taken into consideration * when calculating the average. Only those runs are used that are at most * `consideredRunsEpsilon%` slower than the last run. Additionally, * the last run is only considered if it is at most `consideredRunsEpsilon%` * slower than the average. Hence, it is even possible that the average may rise * during the evaluation of `f`. * @param f The side-effect free function that will be measured. * @param r A function that is called back whenever `f` was successfully evaluated. * The signature is: * {{{ * def r( * lastExecutionTime:Nanoseconds, * consideredExecutionTimes : Seq[Nanoseconds] * ) : Unit * }}} * 1. The first parameter is the last execution time of `f`. * 1. The last parameter is the list of times required to evaluate `f` that are taken * into consideration when calculating the average. * @param runGC If `true` the garbage collector is run using `org.opalj.util.gc()` * before each run. This may be necessary to get reasonable stable behavior between * multiple runs. However, if each run takes very long and the VM has to perform * garbage collection as part of executing f (and also has to increase the JVM's heap) * getting stable measurements is unlikely. */ def time[T]( epsilon: Int, consideredRunsEpsilon: Int, minimalNumberOfRelevantRuns: Int, f: => T, runGC: Boolean = false )( r: (Nanoseconds, Seq[Nanoseconds]) => Unit ): T = { try { require(minimalNumberOfRelevantRuns >= 3) require( consideredRunsEpsilon > epsilon, s"epsilon ($epsilon) < consideredRunsEpsilon ($consideredRunsEpsilon)" ) var result: T = 0.asInstanceOf[T] val e = epsilon.toDouble / 100.0d val filterE = (consideredRunsEpsilon + 100).toDouble / 100.0d var runsSinceLastUpdate = 0 var times = List.empty[Nanoseconds] if (runGC) gc() time { result = f } { t => times = t :: times if (t.timeSpan <= 999 /*ns*/ ) { r(t, times) OPALLogger.warn( "common", s"the time required by the function (${t.toString}) "+ "is too small to get meaningful measurements." )(GlobalLogContext) // Non local-returns will be deprecated in Scala 3 // Replace this by scala.util.control.NonLocalReturns in Scala 3 throw Return[T](result) } } var avg: Double = times.head.timeSpan.toDouble do { if (runGC) gc() time { result = f } { t => if (t.timeSpan <= avg * filterE) { // let's throw away all runs that are significantly slower than the last run times = t :: times.filter(_.timeSpan <= t.timeSpan * filterE) avg = times.map(_.timeSpan).sum.toDouble / times.size.toDouble runsSinceLastUpdate = 0 } else { runsSinceLastUpdate += 1 if (runsSinceLastUpdate > minimalNumberOfRelevantRuns * 2) { // for whatever reason the current average seems to be "too" slow // let's add the last run to rise the average times = t :: times avg = times.map(_.timeSpan).sum.toDouble / times.size.toDouble runsSinceLastUpdate = 0 } } r(t, times) } } while (times.size < minimalNumberOfRelevantRuns || Math.abs(avg - times.head.timeSpan) > avg * e) result } catch { case Return(result) => result.asInstanceOf[T] } } /** * Times the execution of a given function `f`. * * @param r A function that is passed the time that it took to evaluate `f` and the result * produced by `f`; `r` is only called if `f` succeeds. */ def run[T, X](f: => T)(r: (Nanoseconds, T) => X): X = { val startTime: Long = System.nanoTime val result = f val endTime: Long = System.nanoTime r(Nanoseconds.TimeSpan(startTime, endTime), result) } }