When working on performance-sensitive applications, measuring and logging the time a piece of code takes to execute is often essential. Elixir, with its functional and concurrent nature, provides efficient ways to track the performance of functions. In this post, we'll explore how you can log execution times in a smart and human-friendly way.

The basic approach: measuring execution time

Elixir has a built-in function :timer.tc/1 that makes it easy to measure how long a piece of code took to execute. The :timer.tc/1 function returns a tuple, where the first element is the time taken (in microseconds) and the second is the result of the function execution.

Let's look at a simple example:

defmodule MyModule do
  require Logger

  def measure_execution_time do
    {time_in_microseconds, result} = :timer.tc(fn ->
      # Your code here
      :timer.sleep(1000) # Simulating some work
      "Some result"
    end)

    time_in_milliseconds = time_in_microseconds / 1_000
    Logger.info("Execution time: #{time_in_milliseconds} ms")
    result
  end
end

How it works

• :timer.tc/1 takes an anonymous function, runs it, and returns two values: the time it took (in microseconds) and the result of the function.
• The time is logged by converting it from microseconds to milliseconds for a more familiar unit of time.

This approach works great for basic use, but logging all time values in milliseconds might not always be ideal. If your code runs for less than a millisecond or more than a second, having a single unit isn't as intuitive.

A smarter way: human-readable time formatting

To make the logged time more user-friendly, we can format the elapsed time intelligently. For example:

• For operations that take just a few microseconds, we should log the time in microseconds.
• For slightly longer tasks (e.g., hundreds of microseconds to milliseconds), we can display the time in milliseconds.
• For longer tasks, like those that take over a second, it's best to log in seconds.

Implementing smart time formatting

Here's how you can implement this:

defmodule MyModule do
  require Logger

  def measure_execution_time do
    {time_in_microseconds, result} = :timer.tc(fn ->
      # Your code here
      :timer.sleep(1234) # Simulates some work
      "Some result"
    end)

    Logger.info("Execution time: #{format_time(time_in_microseconds)}")
    result
  end

  defp format_time(microseconds) when microseconds < 1_000 do
    "#{microseconds} µs"
  end

  defp format_time(microseconds) when microseconds < 1_000_000 do
    milliseconds = microseconds / 1_000
    "#{Float.round(milliseconds, 2)} ms"
  end

  defp format_time(microseconds) do
    seconds = microseconds / 1_000_000
    "#{Float.round(seconds, 2)} s"
  end
end

What's happening here?

We introduced a helper function format_time/1 that converts the time from microseconds into the most appropriate unit. It works as follows:

1. Microseconds (µs): If the time is less than 1,000 microseconds, we log the time as is, in microseconds.
2. Milliseconds (ms): If the time is between 1,000 microseconds and 1,000,000 microseconds, we convert it to milliseconds.
3. Seconds (s): If the time is greater than or equal to 1,000,000 microseconds, we log it in seconds.

Rounding for readability

To avoid cluttered log messages, we round the milliseconds and seconds to two decimal places using Float.round/2, which helps make the output more readable.

Output Examples

Depending on the time it took to run the function, you'll get appropriately scaled log messages like:

• 500 microseconds: Execution time: 500 µs
• 150 milliseconds: Execution time: 150.0 ms
• 1.234 seconds: Execution time: 1.23 s

This kind of smart formatting is useful because it adjusts the time unit based on the actual duration, making it easier to understand at a glance how long an operation took.

Conclusion

Measuring execution time in Elixir is straightforward with the help of :timer.tc/1, but formatting the elapsed time for readability can significantly improve how performance metrics are interpreted. With a bit of extra logic, you can make your logs more informative and easier to understand, whether your code takes microseconds or seconds to execute.

This approach provides a flexible and smart way to log execution times, helping you keep track of your application's performance in a more intuitive manner. If you're working on performance optimizations or debugging, this simple logging trick can be a valuable addition to your toolkit.