What I Learned at Work This Week: Timing a Method with Object Oriented Principles

Photo by Alex P: https://www.pexels.com/photo/green-and-gray-scissors-2831794/

This week, I was tasked with investigating a latency issue with one of my team’s services. We use Datadog to chart the amount of time it takes for certain processes to run and we create monitors that will go off if that duration exceeds a certain threshold. When the monitors go off, we want to understand what caused the latency so we can improve the process and prevent it in the future.

My investigation didn’t yield much, so I got advice that I should add a log that emits a warning when a certain query, which we suspected was the culprit, was taking too long. I can’t remember which classes create timestamps off the top of my head, so I looked around and found this Stack Overflow post whose top answer had 1,471 upvotes. I tested out some variations of the advice and ended up with this:

long startTime = System.nanoTime();
incomingRequests = incomingRequestRepository.getRequests();
long endTime = System.nanoTime();
long duration = endTime - startTime;
long durationInSeconds = 
    TimeUnit.SECONDS.convert(duration, TimeUnit.NANOSECONDS);
if (durationInSeconds > 60) {
    System.out.println(String.format(
      "getRequests is showing latency. It took %s seconds to run.",
      durationInSeconds
    ));
}

Even as I was writing this, it didn’t *look good* in the codebase. Declaring all these variables, doing conversions on the fly, something was off. Before we get to how it could be improved, let’s look at what’s happening:

The Original Attempt

The System class is a utility that standardizes inputs, outputs, and errors. It includes a method that can output the current time in nanoseconds, which will give us an extremely specific telling of the moment of execution. If we create nano timestamps before and after the method we’re timing, we can subtract them to determine the duration of that method. Then, for readability, we can use the TimeUnit class to convert that number to seconds and conditionally log if the query ran for more than a minute. In this case, we use println but in practice I used a log that was connected to a Datadog instance.

Upon further inspection, I realized that this response was written in 2008. Technically, there is nothing wrong with the solution, but it doesn’t utilize some of the advancements Java has made in the past 17 years.

The Alternative

Let’s look at the suggestion made by the Senior Engineer who reviewed my PR:

var start = Instant.now();

incomingRequests = incomingRequestRepository.getRequests();

var duration = Duration.between(start, Instant.now());
if (duration.compareTo(Duration.ofSeconds(60)) > 0) {
    LOG.warn("getRequests long query: " + duration);
}

First, we’re using var instead of the return type of Instant.now(), which is an Instant. Var is a reserved type name which allows the compiler to infer a variable’s type based on context. I believe it’s useful here because, though start is an Instant, its type is immediately made irrelevant when we determine duration. The Duration class likewise returns a Duration object but again we’re just using it for a comparison, so its type is irrelevant.

The last thing we do is use compareTo to check whether our duration variable is more or less than 60 seconds. compareTo comes from the Comparable interface, which Duration implements. Comparable allows us to “define the natural ordering of objects.” Looking at compareTo specifically, it will return a negative integer if the object it’s called on is less than the argument it’s passed, a 0 if they are equal, and a positive integer if the object it’s called on is greater than the argument. The examples in the doc are helpful if that’s confusing. In our case, we’re checking whether the result is greater than 0 because we want to see if our initial duration is greater than the duration of 60.

Why Does This Matter?

Both solutions use about the same number of lines and about the same number of new classes, so why would we prefer one over the other? One important difference is that the latter invokes the principle of Abstraction, which I wrote about when I was first learning Object Oriented Programming almost five years ago. In describing the concept, I wrote “our objects should only reveal operations relevant to other classes,” which applies here. Rather than exposing the raw arithmetic that determines our method’s duration, we can use abstract, built-in classes. This makes our code more stable and easier to understand.

The truth is, my “original attempt” was not the first code that I wrote to try and make this work. When I first saw the Stack Overflow response, I copied it more faithfully and as a result had a “duration” value set in nanoseconds that I couldn’t understand. I had no idea if the number was even correct. I had to spend more time doing research to figure out the right way to convert nanoseconds into seconds and before I found the TimeUnit class, I was genuinely attempting to divide my results by 1,000,000 right in the code. It was the complete opposite of an abstract solution.

My initial attempt took more time, confused me, and, most importantly, gave me incorrect results because I was doing my conversion math wrong. The value of abstraction is not just that these classes make our lives easier, but they clearly state their intention such that we’re much less likely to make a mistake: Instant.now(), Duration.between(), compareTo().

I’ve read in textbooks like Effective Java not to try and re-invent the wheel. Now, I hope I’ll recognize it more effectively before I start falling into that trap.

Sources

• How do I time a method’s execution in Java?, Stack Overflow
• System, Instant, and Duration, Oracle
• var keyword in Java, Geeks for Geeks
• Java Comparable Interface, Geeks for Geeks