Repo.query!("select pg_sleep(5)", [], timeout: 1_000)

I’ve got this handy function for returning telemetry spans on a particular function:

def trace_ecto(fun) when is_function(fun, 0) do
    this_process = self()

    ref = make_ref()

    # here we're attaching a handler to the query event. When the query is performed in the same process as called this function
    # we want to basically "export" those values out to a list for investigation. Handlers are global though, so we need to
    # only `send` when we are in the current process.
    :telemetry.attach(
      "__help__",
      [:sensetra, :repo, :query],
      fn _, measurements, metadata, _config ->
        if self() == this_process do
          send(this_process, {ref, %{measurements: measurements, metadata: metadata}})
        end
      end,
      %{}
    )

    Repo.transaction(fun)

    :telemetry.detach("__help__")

    do_get_trace_messages(ref)
  end

  defp do_get_trace_messages(ref) do
    receive do
      {^ref, message} ->
        [message | do_get_trace_messages(ref)]
    after
      0 -> []
    end
  end

Basically you call trace_ecto(fn -> your_funciton_here() end) and it returns all of the ecto telemetry emitted by that function!

EDIT: Oh on second thought I really need to set it up to rescue or something to catch those timeouts as the actual return value. You still get them from the send though it just ends up in your mailbox and you have to flush() them out. Will post an updated version shortly.

You should consider integrating OpenTelemetry with OpenTelemetryEcto that will capture spans for your Ecto queries, and then ship them to a good observability tool like https://www.honeycomb.io/ or https://www.servicenow.com/products/observability.html

I wrote about this around a year ago and there’s another good post that goes into more practical detail

One of the more recent versions of Ecto added a stacktrace: true option that you can set on the repo. This provides a stacktrace for the query in the ecto telemetry handlers.

From there it’s mostly a matter of figuring out how you want to consume that information. The quick and dirty way is to just log any queries that took longer than a chosen threshold.

You do indeed! Here is an example of the metadata arg value in such a case:

%{
     cast_params: nil,
     options: [],
     params: [],
     query: "select pg_sleep(5)",
     repo: Sensetra.Repo,
     result: {:error,
      %DBConnection.ConnectionError{
        message: "tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)",
        severity: :error,
        reason: :error
      }},
     source: nil,
     stacktrace: nil,
     type: :ecto_sql_query
   }
 }

Stacktrace is nil in this case because I was running this from iex.

Before moving forward with integration with OpenTelemetry & Cloud Traces in Google Cloud, we’ve implemented a very simple way to match “slow queries” to the code. It’s based on small piece of code that:

1. creates an ETS table,
2. attaches a telemetry handler to write queries and stacktraces (and a single sample of query parameters for that query) to the ETS table,
3. a function to scan ETS table for a matching query using a string fragment of the query.

Sample parameters are not really necessary, but are a convenience to be able to later quickly re-run the query, or assemble an EXPLAIN (...) from it. On a typical day our app issues maybe under 1000 unique SQL queries. The in-memory size of ETS table I’ve seen so far was well under 20 megabytes.

The script looks like this:

defmodule EctoStacktraces do
  def setup() do
    :ets.new(:queries_and_stacktraces, [:set, :named_table, :public])
    :telemetry.attach("ecto-stacktrace-tracking", [:my_application, :repo, :query], &handle_event/4, %{})
  end

  def filter(string) do
    {:ok, regex} =
      string
      |> Regex.escape()
      |> Regex.compile()

    find = fn {query, _stacktrace, _cast_params, _measurements} = item, acc ->
      if String.match?(query, regex) do
        [item | acc]
      else
        acc
      end
    end

    :ets.foldl(find, [], :queries_and_stacktraces)
  end

  def handle_event([:my_application, :repo, :query], measurements, metadata, _config) do
    :ets.insert(:queries_and_stacktraces, {metadata[:query], metadata[:stacktrace], metadata[:cast_params], measurements})
  end
end

Knowing a slow query reported by tools like “Query Insights” (feature of Google Cloud SQL):

image1200×371 35.4 KB

…we’ve been able to track suspicious down to the code using this technique:

1. run:

   EctoStacktraces.setup()
   

   This is done either by connecting to a running node remotely, or as part of application.ex for example,

2. some time goes by to let the slow query manifest itself,

3. then, knowing INNER JOIN (SELECT ARRAY_AGG(sf0."path") is part of the slow query:

   [{query, stacktrace, _sample_params, _measurements}] =
     EctoStacktraces.filter(~s{INNER JOIN (SELECT ARRAY_AGG(sf0."path")})
   
   IO.inspect(stacktrace)
   

This part INNER JOIN (SELECT ARRAY_AGG(sf0."path") is taken from a service that reports slow queries, in our case it’s “Query Insights” feature in Google Cloud:

The above is very simple and obviously doesn’t survive process exit, for example detaching from a remote session, or restarting the application. But it helped us move forward with optimising several long-standing hard-to-locate SQL queries in the app. Also, looking at some of the stacktraces helped reveal code that hides calls to DB in private functions, that don’t show up in the stacktrace