gmile

Tracking down slow queries in Ecto

Sometimes, Ecto (actually, DBConnection) spills an error like this:

DBConnection.ConnectionError: ** (DBConnection.ConnectionError) connection not available and request was dropped from queue after 11963ms. This means requests are coming in and your connection pool cannot serve them fast enough. You can address this by:

  1. Ensuring your database is available and that you can connect to it
  2. Tracking down slow queries and making sure they are running fast enough
  3. Increasing the pool_size (although this increases resource consumption)

Item 2 in the list above suggests Tracking down slow queries. How do you locate the code that is sending a slow query to database, in production?

I’m curious how this can be done at scale because, for example, the codebase I am working on is vast, spanning over 1000 modules. There are tons of places in the code that may call database, and finding the right code is not that easy.

I recently noticed telemetry produced by Ecto includes stacktrace info, so maybe this could help tracing down code that produces slow queries. Has anyone tried that? If yes, how do you log/collect/store such stacktraces?

22 comments

#ecto #performance #ecto-query #monitoring

3 2595 22

2023-09-22 09:12:33 UTC

First Post!

D4no0

I would investigate first if this is actually related to slow queries, because the error is network related, there is a different error for query timeout.

Post #1

Most Liked

benwilson512

Author of Craft GraphQL APIs in Elixir with Absinthe

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.

Post #7

davydog187

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

Post #15

benwilson512

Author of Craft GraphQL APIs in Elixir with Absinthe

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.

Post #2

Last Post!

gmile

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:

creates an ETS table,
attaches a telemetry handler to write queries and stacktraces (and a single sample of query parameters for that query) to the ETS table,
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):

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

run:
```
EctoStacktraces.setup()
```
This is done either by connecting to a running node remotely, or as part of application.ex for example,
some time goes by to let the slow query manifest itself,

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