Neat and simple way to measure code performance in Scala

When we write a source code we often have to be aware of the performace of our solution. The easiest way to achieve this is by measuring duration of the execution by taking the system time before and after our block code, ie.

Where is the problem?

val startTime = System.nanoTime
timeConsumingOperations()
val endTime = System.nanoTime

println("Operations took " + (endTime - startTime) + " nano seconds")

This is most basic approach that can be used in the simplest cases. But what if we want to measure times of multiple different operations? This simple solution would become a little complex and harder to maintain, ie.

val startTime = System.nanoTime
operation1()
val middleTime1 = System.nanoTime
operation2()
val middleTime2 = System.nanoTime
operation3()
val endTime = System.nanoTime

println("Operation1 took " + (middleTime1 - startTime) + " ns")
println("Operation2 took " + (middleTime2 - middleTime1) + " ns")
println("Operation3 took " + (endTime - middleTime2) + " ns")

That code is becoming hard to read, maintain and, in my opinion the worst, it almost hides our business code.
Now let's compilcate it even more by assuming that we need to run those operations multiple times (ie. in a for loop) and we need to measure their entire time of execution. We could try to do something like that:

var operation1Duration = 0L
var operation2Duration = 0L
var operation3Duration = 0L

for(i <- 1 to 10) {
  val startTime = System.nanoTime
  operation1()
  val middleTime1 = System.nanoTime
  operation2()
  val middleTime2 = System.nanoTime
  operation3()
  val endTime = System.nanoTime

  operation1Duration += middleTime1 - startTime
  operation2Duration += middleTime2 - middleTime1
  operation3Duration += endTime - middleTime2
}
println("Operation1 took " + operation1Duration + " ns")
println("Operation2 took " + operation2Duration + " ns")
println("Operation3 took " + operation3Duration + " ns")

And that is an ugly piece of code.

Solution Proposal

I propose a simple solution to that problem, a simple stopwatch. With this stopwatch we can refactor our third case into this:

clearStopwatchResults()

for(i <- 1 to 10) {
  stopwatch("First operation") {
    operation1()
  }
  stopwatch("Second operation") {
    operation2()
  }
  stopwatch("Third operation") {
    operation3()
  }
}

println(stopwatchResults)

And the result of this measurement would be something like this:

Third operation -> 48 ms 355 us 124 ns 
First operation -> 136 ms 219 us 210 ns 
Second operation -> 644 ms 69 us 657 ns

Basic idea for that approach is to create a Stopwatch that can measure execution time of a block of code and store it under given identifier (ie. "First operation"). It will accumulate a time of execution for given identifier, and in the end it will write out the measurement results in a readable format.

Solution Implementation

So here is the implementation of my Stopwatch:

import collection.mutable
import scala.StringBuilder

class Stopwatch {

  private val measurements = mutable.HashMap[Any, Long]()

  def clearResults() {
    measurements.clear()
  }

  def apply(identifier:Any)(codeBlock: => Unit) {
    val start = System.nanoTime
    codeBlock
    val end = System.nanoTime
    val oldValue = measurements.getOrElse(identifier, 0L)
    measurements += identifier -> (oldValue + end - start)    
  }

  def results():String = {
    ResultsFormatter.format(measurements)
  }
}

And there is also a companion object to provide default Stopwatch and convenient methods to use it.

object Stopwatch {
  private val defaultStopwatch = new Stopwatch

  def stopwatch(identifier:Any)(codeBlock: => Unit) {
    defaultStopwatch(identifier)(codeBlock)
  }

  def stopwatchResults() = defaultStopwatch.results()

  def clearStopwatchResults() {
    defaultStopwatch.clearResults()
  }
}

To complete the solution we also need a class to format our measurements results into well formatted String:

object ResultsFormatter {
  def format(measurements: mutable.HashMap[Any, Long]):String = {
    val sb = new StringBuilder
    measurements.foreach(appendResult(sb))
    sb.toString()
  }

  private def appendResult(sb: StringBuilder)(result: (Any, Long)) {
    val identifier = result._1
    val value = result._2
    sb.append(identifier).append(" -> ")

    appendIfNotZero(sb, extractSeconds(value), "s")
    appendIfNotZero(sb, extractMills(value), "ms")
    appendIfNotZero(sb, extractMicro(value), "us")
    appendIfNotZero(sb, extractNano(value), "ns")

    sb.append('\n')
  }

  private def extractNano(value: Long): Long = value % 1000
  private def extractMicro(value: Long) = (value / 1000) % 1000
  private def extractMills(value: Long) = (value / 1000000) % 1000
  private def extractSeconds(value: Long) = value / 1000000000

  private def appendIfNotZero(sb:StringBuilder, value:Long, suffix:String) {
    if (value > 0) {
      sb.append(value).append(" ").append(suffix).append(" ")
    }
  }
}

I have to mention that this is not thread safe implementation and one instance of Stopwatch should be use within single thread.

Implementation description

Stopwatch class
The main point of the implementation is a Map called measurements. It is a mutable HashMap, for higher performance and it is used to map identifier into execution duration.

The Stopwatch class provides three public methods:
- apply(identifier:Any)(codeBlock: => Unit) - This method takes an identifier and a code block that will be measured. It simply calls the codeBlock, calculates how long it took to execute it and in the end it accumulates the result in the measurements map.
I think the method declaration requires a little more explanation. First it uses a feature called currying. For our purpose we can assume that it allows us to define function parameters in multiple parentheses pairs (of course currying is much more and it can be used for other purposes, but this is topic for other aricle) instead of one. Also codeBlock: => Unit part defines a function that takes no parameters, or just a code block surrounded by curly brackets { ... }.
Thanks to that we could call apply method in this way (full syntax):

apply("some computation")({complexComputation()})

or we can omit latter parentheses and write simply:

apply("some computation"){complexComputation()}

We wouldn't be able to do this, in such a nice way, if we would use only one parameters block, ie. apply(identifier:Any, codeBlock: => Unit)
- clearResults() - This method simply clears the measurements map to allow new measurements to be performed.
- result() - Returns a well formatted String representation of measurements result.

As you can see, the core imlpementation of this solution is very clear and simple. Also this is very easy to add new functionalities to this class.


Stopwatch companion object
This companion object is used to increase the ease of using Stopwatch class. It provides default instance of Stopwatch and provides a convenient methods to use it. To use those methods we have to import this object into current namespace by:

import Stopwatch._

This import statement will include all methods from Stopwatch object into current namespace, so we can call it directly, without passing Stopwatch name.


ResultsFormatter class
This class is simpy used to create a well formatted String from Map containing measurement results.

Conclusion

I think that this approach to code performance measurement is well suited for many use cases, when you don't want to use external libraries for microbenchmarking or use of external profilers. Scala is very flexible language that allows us to create simple and very elegant solution for that kind of problems.
Of course my Stopwatch is very simple, and I can imagine many ways to improve it. In example it can be rebuilt to be thread safe, or internal map can be replaced by simple array to increase its performance. But I also think that this is a good point to start for most of the projects.

Next article: Metaprogramming in Scala with higher order functions
Previous article: Scala - Parentheses and Curly Brackets in Anonymous Functions