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 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. James Halliday-like 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 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: an additional Ecto logger 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. : the trace back to the app code that generated the query isn’t available inside . If you attempt to fetch the backtrace via inside , it won’t lead back to your custom application code. Instead, you’ll see a backtrace like this — , for example: But, there’s a problem trace/1 Process.info/2 Ecto.LogTrace.trace/1 notice there’s no references to a controller PSA: don’t want to mess with this? We’re building at my day job that does most of this for you. . Elixir App Monitoring Signup for early access Now what? Let’s override the public Ecto query functions. : 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. This is not ideal Therein lies the danger of metaprogramming. The plan: Have our app’s expand a macro we define in a module we’ll create. repo.ex SlowLogger.Ecto will dynamically create a new module, that wraps around the Ecto query functions. We’ll be able to time their execution and grab backtraces. SlowLogger.Ecto YourApp.Repo.SlowLogger Alias as so our queries will be traced by default. YourApp.Repo.SlowLogger Repo repo.ex Here’s our updated Repo module: SlowLogger.Ecto When this module is used by , a new module, , is created dynamically. How meta! This module wraps around the Ecto query functions like , , and . We’ll be able to time their execution and grab backtraces. repo.ex YourApp.Repo.SlowLogger query all update . . Let’s walk through it. This is the meat of the implementation Here’s the module source How can we override Ecto functions? Technically, we can’t. Elixir functions can only be directly overwritten if they are referenced via the keyword. The Ecto functions that run queries — , , , etc — aren’t listed as overridable. [defoverridable](https://hexdocs.pm/elixir/Kernel.html#defoverridable/1) all query update We can work around this. We’ll dynamically create a new module. This module is included in our module, and we’ll define functions that wrap calls to the module that required it like . Repo unquote(__MODULE__).query(a) **Module.__using__/1** This is called when when the macro is invoked inside . Typically this is done to to inject functions inside the calling module ( ), and in this case, that code creates an entire submodule. [use](http://www.zohaib.me/use-in-elixir-explained/) repo.ex YourApp.Repo 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 block. The outer block is placed in the calling module via . The inner quote block contains function definitions that are assigned to a variable. The block generates a free-standing piece of code: it isn’t executed immediately. quote quote use content quote **__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 block and creates our new module that traces our Repo queries. We’ll use this module vs. to run Ecto queries. quote YourApp.Repo web.ex We’ll alias the dynamically created module, , in so our calls to are routed through our tracing: YourApp.Repo.SlowLogger web.ex Repo 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 to . web.ex YourApp.Repo.SlowLogger Add the logger to : Ecto config.exs config :yourapp, YourApp.Repo,    loggers: [{Ecto.LogEntry, :log, []}, {Ecto.LogTrace, :trace, []}] 3. Drop into your folder. [SlowLogger.Ecto](https://gist.github.com/itsderek23/f83a3f24d9a417c87da4993e8ce9db48) lib/ 4. Drop into your folder. [Ecto.LogTrace](https://gist.github.com/itsderek23/03c29bd3077b6e17a43f5233221eb8b3) lib/ 5. Add the following line to your file: repo.ex use SlowLogger.Ecto. PSA: Whew…too many steps? We’re building at my day job that does most of this for you. . Elixir App Monitoring Signup for early access

Fetch

Trace

Read My Stories

Too Long; Didn't Read

In your car, at home, or at work — Bosch technology shapes many areas of life.

Logging slow Ecto queries: adventures in metaprogramming

Too Long; Didn't Read

Companies Mentioned

Derek Haynes

About Author

TOPICS

THIS ARTICLE WAS FEATURED IN...

Logging slow Ecto queries: adventures in metaprogramming

Too Long; Didn't Read

Companies Mentioned

Derek Haynes

About Author

TOPICS

THIS ARTICLE WAS FEATURED IN...

RELATED STORIES