Tracking down slow queries in Ecto

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.

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.

Assuming this is not the fault of the network as @D4no0 said, my second item on the list would be to inspect the telemetry traces; they should include duration.

Though I’m not sure they’re sent at all in case of timeouts.

You could temporarily override your Repo and have it make a root telemetry span if you can’t find them in your monitoring system.

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.

Ha, cute. How do you cause a timeout like this btw?

APM in Datadog helps a lot

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.

Thanks for mentioning this! We’re actually using AppSignal, I opened an issue to see if support for stacktrace can be implemented there: Collect Ecto stacktraces · Issue #885 · appsignal/appsignal-elixir · GitHub

Just keep in mind, that having a stacktrace in production comes with a performance cost.
Even without stacktrace, when an exception occurs, it should close the span/trace with the error, so you should be able to identify the place by looking at the trace.

It does but we haven’t found it to be an issue in practice. We do something on the order of 1000 ecto queries per second sustained and the stacktrace overhead isn’t noticeable.