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?
Most Liked
benwilson512
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.
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
benwilson512
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.
Popular in Questions
Other popular topics
Categories:
Sub Categories:
Forums
Popular Tags
- #ecto
- #liveview
- #troubleshooting
- #learning-elixir
- #deployment
- #library
- #erlang
- #testing
- #genserver
- #mix
- #absinthe
- #remote-other
- #otp
- #plug
- #how-to-question
- #macros
- #postgres
- #channels
- #elixirconf
- #exunit
- #discussion
- #code-sync
- #javascript
- #podcasts
- #onsite
- #dialyzer
- #docker
- #authentication
- #umbrella
- #full-time-contract
- #podcasts-by-brainlid
- #ecto-query
- #elixir-ls
- #phoenix_html
- #iex
- #blog-post
- #graphql
- #genstage
- #ai
- #websockets
- #supervisor
- #advent-of-code
- #elixirconf-us
- #distillery
- #processes
- #forms
- #api
- #metaprogramming
- #security
- #performance








