Scala Tutorial: Applying the DIP to Metrics Libraries

The D in SOLID stands for the Dependency Inversion Principle, sometimes shortened to DIP. The SLAP and my thoughts on Telescoping Methods are possibly restatements of the DIP. At the very least they are closely related! But let’s do what we always do here and get out of theory and into practice.

The Example of Timers

Most applications in production make use of some metrics code to take various measurements and assess whether or not it is meeting its requirements. There are myriad approaches to this because different applications have different requirements. Some are more concerned with availability while others care more about throughput or something else. So that we don’t get bogged down in hypotheticals let’s take the one thing that applies across all of them: measuring how long a task takes.

How do I time a method’s execution in Java?
Many people still believe that the best way to do this is manually by calling System.currentTimeMillis() before and after the task and then computing the difference. If you Google “How do I time a method’s execution in Java?” the first result is a Stack Overflow page with this answer:

There is always the old-fashioned way:

long startTime = System.nanoTime();
methodToTime();
long endTime = System.nanoTime();

long duration = (endTime - startTime);  //divide by 1000000 to get milliseconds.

Naively Applying it
That’s the first Google result so let’s just run with it. Our example is general so for now we’ll literally just write a method that pauses execution for up to ten seconds:

import scala.util.Random
import java.util.concurrent.TimeUnit

object RandomTask {

  def run() = {
    val randomTaskTime = new Random(System.nanoTime()).nextInt(10000)
    TimeUnit.MILLISECONDS.sleep(randomTaskTime)
  }

}

Given the RandomTask object I can now call RandomTask.run() anywhere.

To implement a timer around that method, I will need code like this:

import org.slf4j.LoggerFactory

object Demo extends App {

  private val Logger = LoggerFactory.getLogger(Demo.getClass)

  val start = System.nanoTime()
  RandomTask.run()
  val end = System.nanoTime()
  val durationInSeconds: Double = (end - start) / 1000000000D
  Logger.info(f"The task took $durationInSeconds%2.2f seconds to complete")

}

I’ve simply logged the duration after the method finishes execution so that you could take this code and run it in your environment if you wanted. In a real world application, you will probably want to persist that value somewhere so you can aggregate some statistics later.

So is there any problem with this?
Yes. Yes there is. We just saw that we need at least four lines of extra code (lines 7, 9-11) in every place that we want to time a method’s execution. This isn’t just a bummer because of code clutter and readability. It is also fraught with perilous bugs. What if someone mixes use of System.nanoTime() and System.currentTimeMillis()? What if they swap end and start? What if they don’t divide by the exact right value (in this case 1000000000D)? (I have actually seen this last bug in a production codebase personally.)

On top of that, this will be very hard to update later. If you allow developers in your codebase to copy/paste these blocks of code around every method that needs timed then what happens if your team ever decides to switch over to something better like a first-rate metrics library such as DropWizard metrics? Especially when the number of methods in the application grows to a sizable number. It’s not crazy to think that there will be ten’s to hundred’s of methods you potentially want to time.

Believe it or not, this is the archetypal problem that the Dependency Inversion Principle solves.

How does the DIP apply here?

The principle states:

A. High-level modules should not depend on low-level modules. Both should depend on abstractions.
B. Abstractions should not depend on details. Details should depend on abstractions.

— Robert C. Martin, Agile Software Development, Principles, Patterns, and Practices

The problem in our timer example is that high-level modules (containing the random tasks we want to perform) are now dependent on low-level modules (system time and logging). Instead, we should depend on an abstraction–to be precise, a timer abstraction.

A Timer Abstraction

The code above has four parts:

  1. Start timer before task
  2. Stop timer after task
  3. Compute the duration
  4. Persist the duration

But those are the four things we are currently doing because of how the language works and how there are some low-level details need to be taken care of. In reality, we just want to “time the task.” So we definitely have a design choice. Since functions are first-class citizens in Scala, we might translate this plain language (“time the task”) into a timer trait with a method that accepts a passed function:

trait Timer {

  def apply[A](taskName: String)(fn: => A): A

}

You may also take other approaches depending on the use case. Maybe you want the ability to control when the timer is started and stopped. In that case you can add that to your trait.

Implementing it
Using the existing System.nanoTime based method we got from SO, you might implement it in a NanoTimer object:

import org.slf4j.LoggerFactory

object NanoTimer extends Timer {

  private val Logger = LoggerFactory.getLogger(NanoTimer.getClass)

  override def apply[A](taskName: String)(fn: => A): A = {
    val startTime = System.nanoTime()
    val result: A = fn
    val endTime = System.nanoTime()
    val elapsedSeconds = Timer.nanosToSeconds(endTime - startTime)
    Logger.info(s"$taskName took $elapsedSeconds seconds")
    result
  }

}

This would allow you to call RandomTask.run() as follows:

import com.scottshipp.www.timer.{NanoTimer => timer}
import org.slf4j.LoggerFactory

object Demo extends App {

  val Logger = LoggerFactory.getLogger(Demo.getClass)

  timer("Random task") {
    RandomTask.run()
  }

}

Output from this looks similar to:


12:10:59.382 [main] INFO - Random task took 3.21 seconds

Taking advantage of the DIP

Now what did we gain? Well, these were the problems we mentioned before:

  • Clutter / extra lines of code everywhere
  • Possible bugs
  • Hard to change the implementation

We solved all of these: The timer block around our method call is concise, it can’t be mistyped without the compiler flagging it, and we can now easily change implementations.

For example, let’s say you read about the Google Guava Stopwatch. Among other benefits it touts the following:

As documented by nanoTime, the value returned has no absolute meaning, and can only be interpreted as relative to another timestamp returned by nanoTime at a different time. Stopwatch is a more effective abstraction because it exposes only these relative values, not the absolute ones.

That’s great and all but would your boss let you take time away from other important work just because Google Guava has a cool stopwatch? In a normal application implemented without this timer abstraction, you would see a lot of friction to make the change. People will be worried about you going through the entire codebase to change over to this new class. You might break things. And you are adding yet another dependency.

But in this application, since we followed the DIP, we simply implement a new timer object:

import java.util.concurrent.TimeUnit
import org.slf4j.LoggerFactory

import com.google.common.base.Stopwatch

object GuavaTimer extends Timer {

  val Logger = LoggerFactory.getLogger(GuavaTimer.getClass)

  override def apply[A](taskName: String)(fn: => A): A = {
    val stopwatch = Stopwatch.createStarted()
    val result: A = fn
    val elapsedSeconds = Timer.nanosToSeconds(stopwatch.stop().elapsed(TimeUnit.NANOSECONDS))
    Logger.info(s"$taskName took $elapsedSeconds seconds")
    result
  }

}

Our Demo object does change slightly, to use of GuavaTimer instead of NanoTimer . . . something that would be eliminated if we were using a DI framework but isn’t too painful even in this simplistic demo code:

import com.scottshipp.www.timer.{GuavaTimer => timer}
import org.slf4j.LoggerFactory

object Demo extends App {

  val Logger = LoggerFactory.getLogger(Demo.getClass)

  timer("Random task") {
    RandomTask.run()
  }

}

But wait . . .

Uh oh. Something is wrong, even though you’re using the cool Google Guava Stopwatch! In production, sometimes your timer readings are definitely not correct. No one knows what is going on. You can’t reproduce the issue locally, but something is definitely not right! What happened!?

I wonder…did you read the Google Guava Stopwatch JavaDoc?

The part where it says:

Note: This class is not thread-safe.

Uh…yeah.

So you consult with various parties and you learn that DropWizard Metrics is thread-safe! Time to update again. Thank goodness you only have to update your code in one place!

import com.codahale.metrics.{Meter, MetricRegistry, Timer => DropWizardTimer}
import org.slf4j.LoggerFactory

object DWTimer extends Timer {

  val Logger = LoggerFactory.getLogger(DWTimer.getClass)
  val metrics: MetricRegistry = new MetricRegistry()
  val meter: Meter  = metrics.meter("DWTimer")

  override def apply[A](taskName: String)(fn: => A): A = {
    val timer: DropWizardTimer = metrics.timer("timer")
    val context = timer.time()
    val result: A = fn
    val elapsedSeconds = Timer.nanosToSeconds(context.stop())
    Logger.info(s"$taskName took $elapsedSeconds seconds")
    result
  }

}

* Note that this is not what you would actually implement, but it works for demo purposes.

That, my friends, is the power of the dependency inversion principle (DIP)! By depending on an abstraction rather than a concrete lower-level detail, you are insulated from many different problems!

Additional Reading

Uncle Bob on the Principles of OOP
Thoughtworks’ article ‘DIP in the Wild’

Martin, Robert C. (2003). Agile Software Development, Principles, Patterns, and Practices. Prentice Hall. pp. 127–131. ISBN 978-0135974445.

Leave a Reply

Your email address will not be published. Required fields are marked *