Travis Warren via Flickr
Slow database queries are a regular thorn in my side. Whether it’s missing indexes, expensive joins, or N+1s, database performance woes have a way of surfacing in a multitude of ways.
That’s why tracking down the source of slow queries is so important. While Postgres can easily log slow queries, there’s no way to track that back to the line-of-code emitting the query. That’s a problem.
We can solve this with the most James Halliday-like tool from the Elixir developer toolbox: metaprogramming. By the end of this article, you’ll wield your metaprogramming powers in a worthwhile pursuit: identifying the source of slow Ecto queries in a Phoenix app.
The goal: logging the source of slow Ecto queries
For every Ecto query greater than 500 ms, we want to log the query execution time, the raw SQL, and a backtrace to the source:
Where to begin?
Adding an additional Ecto logger seems like a clear starting point, right? We don’t even need metaprogramming! This give us access to the raw query and its execution time. Here I’m logging all queries that take longer than 500 ms:
Example output:
[info] Slow!!!!: SELECT g0."id", g0."install_id", g0."email", g0."raw_payload", g0."deleted_at", g0."inserted_at", g0."updated_at" FROM "github_integrations" AS g0
Now, we just the need backtrace and we’re done.
But, there’s a problem: the trace back to the app code that generated the query isn’t available inside trace/1. If you attempt to fetch the backtrace via Process.info/2 inside Ecto.LogTrace.trace/1, it won’t lead back to your custom application code. Instead, you’ll see a backtrace like this — notice there’s no references to a controller, for example:
PSA: don’t want to mess with this? We’re building Elixir App Monitoring at my day job that does most of this for you. Signup for early access.
Now what?
Let’s override the public Ecto query functions. This is not ideal: we need to ensure we override all of the functions. If the function signatures or names change in later versions, we’ll fail to capture some slow queries and/or possibly break at compile time.
Therein lies the danger of metaprogramming.
The plan:
- Have our app’s
repo.exexpand a macro we define in aSlowLogger.Ectomodule we’ll create. SlowLogger.Ectowill dynamically create a new module,YourApp.Repo.SlowLoggerthat wraps around the Ecto query functions. We’ll be able to time their execution and grab backtraces.- Alias
YourApp.Repo.SlowLoggerasReposo our queries will be traced by default.
repo.ex
Here’s our updated Repo module:
SlowLogger.Ecto
When this module is used by repo.ex, a new module, YourApp.Repo.SlowLogger, is created dynamically. How meta! This module wraps around the Ecto query functions like query, all, and update. We’ll be able to time their execution and grab backtraces.
This is the meat of the implementation. Here’s the module source. Let’s walk through it.
How can we override Ecto functions?
Technically, we can’t. Elixir functions can only be directly overwritten if they are referenced via the[defoverridable](https://hexdocs.pm/elixir/Kernel.html#defoverridable/1) keyword. The Ecto functions that run queries — all, query, update, etc — aren’t listed as overridable.
We can work around this. We’ll dynamically create a new module. This module is included in our Repo module, and we’ll define functions that wrap calls to the module that required it likeunquote(__MODULE__).query(a).
**Module.__using__/1**
This is called when when the [use](http://www.zohaib.me/use-in-elixir-explained/) macro is invoked inside repo.ex. Typically this is done to to inject functions inside the calling module (YourApp.Repo), and in this case, that code creates an entire submodule.
The [**quote**](http://elixir-lang.org/getting-started/meta/quote-and-unquote.html) macro
We’ve defined the Ecto functions we wish to trace for slow queries inside a doubly-nested quote block. The outer quote block is placed in the calling module via use. The inner quote block contains function definitions that are assigned to a content variable. The quote block generates a free-standing piece of code: it isn’t executed immediately.
**__trace/1**
This does the actual tracing: we record the start_time, call the function, and record the end_time.
**Module.create/3**
Module.create(slow_logger_repo_module, contents, __ENV__)
This takes the content from the inner quote block and creates our new module that traces our Repo queries. We’ll use this module vs. YourApp.Repo to run Ecto queries.
web.ex
We’ll alias the dynamically created module, YourApp.Repo.SlowLogger, in web.ex so our calls to Repo are routed through our tracing:
Boom! Traces!
We’re now logging traces to slow Ecto function calls.
Can I have both the raw SQL and backtraces?
At this point, we know how to:
- Log the raw SQL of slow queries
- Log backtraces to slow Ecto function calls
We haven’t married them together: seeing both the raw SQL of a slow query and the associated backtrace to its source code location gives the complete picture.
Process/put and Process/get
Our wedding band will be Elixir’s Process dictionary. Store the log entry in the Process dictionary and fetch it from our tracing logic.
In our Ecto logger, we’ll put the log entry in the Process dictionary:
…and get the log entry inside __trace/1:
log_entry = Process.get(:ecto_log_entry)
Boom! We’ve got everything:
TL;DR
Here’s instructions for logging slow Ecto queries:
-
Change the Repo alias in
web.extoYourApp.Repo.SlowLogger. -
Add the
Ectologger toconfig.exs:config :yourapp, YourApp.Repo, loggers: [{Ecto.LogEntry, :log, []}, {Ecto.LogTrace, :trace, []}]
3. Drop [SlowLogger.Ecto](https://gist.github.com/itsderek23/f83a3f24d9a417c87da4993e8ce9db48) into your lib/ folder.
4. Drop [Ecto.LogTrace](https://gist.github.com/itsderek23/03c29bd3077b6e17a43f5233221eb8b3) into your lib/ folder.
5. Add the following line to your repo.ex file: use SlowLogger.Ecto.
PSA: Whew…too many steps? We’re building Elixir App Monitoring at my day job that does most of this for you. Signup for early access.