How to Log Long-Running Ecto Queries with Stack Traces in Elixir for optimising Performance

Slow database queries can hurt your app’s performance. To identify and fix these issues in Elixir, you need to know which queries take too long and where they originate in your code. In this guide, you’ll see how to log long-running queries in Ecto and capture the stack trace using Telemetry.

How to ?

Step 1: Update the Repo Module

In lib/my_app/repo.ex, capture the stack trace and query

defmodule MyApp.Repo do
  use Ecto.Repo, otp_app: :my_app, adapter: Ecto.Adapters.Postgres

  def log(entry) do
    stack_trace = Process.info(self(), :current_stacktrace) |> elem(1)
    formatted_trace = Enum.map(stack_trace, &Exception.format_stacktrace_entry/1) |> Enum.join("\n")

    :telemetry.execute([:my_app, :repo, :query], %{query_time: entry.query_time}, %{query: entry.query, stacktrace: formatted_trace})
  end
end

Step 2: Telemetry Handler

Create a Telemetry handler to log queries that take longer than 10ms:

defmodule MyApp.LongRunnerQueriesReporter do
  require Logger

  def log_long_queries(_event, measurements, metadata, _config) do
    query_time_ms = System.convert_time_unit(measurements[:query_time], :native, :millisecond)
    
    if query_time_ms > 10 do
      Logger.info("""
      Long Query Detected (#{query_time_ms}ms):
      Query: #{metadata[:query]}
      Stacktrace: #{metadata[:stacktrace]}
      """)
    end
  end
end

Step 3: Attach Telemetry in the Application

Attach the Telemetry event in lib/my_app/application.ex:

:telemetry.attach("log-long-queries", [:my_app, :repo, :query], &MyApp.Telemetry.log_long_queries/4, nil)

And done!

That’s a quick and easy way to log long-running queries with stack traces!