记录慢速 Ecto 查询:元编程历险记
记录慢速 Ecto 查询:元编程历险记
原文：https://medium.com/hackernoon/logging-slow-ecto-queries-adventures-in-metaprogramming-110f3472be33
Travis Warren via Flickr
缓慢的数据库查询是我的一大烦恼。无论是缺少索引、昂贵的连接还是 N+1，数据库性能灾难都会以多种方式出现。
这就是为什么追踪缓慢查询的来源如此重要。虽然 Postgres 可以很容易地记录缓慢的查询，但是没有办法追踪到发出查询的代码行。这是个问题。
我们可以用 Elixir 开发者工具箱中最像 James Halliday 的工具来解决这个问题:元编程。到本文结束时，您将在一项有意义的工作中运用您的元编程能力:识别 Phoenix 应用程序中缓慢的 Ecto 查询的来源。
目标:记录慢速 Ecto 查询的来源
对于每个超过 500 毫秒的 Ecto 查询，我们希望记录查询执行时间、原始 SQL 和对源的回溯:
从哪里开始？
添加一个额外的 Ecto logger 似乎是一个清晰的起点，对吗？我们甚至不需要元编程！这使我们能够访问原始查询及其执行时间。这里我记录了所有耗时超过 500 毫秒的查询:
示例输出:
[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现在，我们只需要回溯就行了。
但是，有一个问题:在trace/1中不能追溯到生成查询的应用程序代码。如果您试图通过Ecto.LogTrace.trace/1内部的Process.info/2获取回溯，它不会返回到您的定制应用程序代码。相反，您将看到这样的回溯— 注意，这里没有对控制器的引用，例如:
PSA:不想搞这个？我们正在构建 Elixir 应用程序监控在我的日常工作中，它会为你完成大部分工作。 提前预约 。
现在怎么办？
让我们覆盖公共的 Ecto 查询函数。这并不理想:我们需要确保覆盖所有的函数。如果函数签名或名称在以后的版本中改变了，我们将无法捕获一些缓慢的查询和/或可能在编译时中断。
元编程的危险就在于此。
计划是:
- 让我们的应用程序的
repo.ex扩展我们在将要创建的SlowLogger.Ecto模块中定义的宏。 SlowLogger.Ecto将动态创建一个新的模块YourApp.Repo.SlowLogger，它包装了 Ecto 查询函数。我们就能确定他们的执行时间并追踪他们的行踪。- 别名
YourApp.Repo.SlowLogger为Repo，这样我们的查询将被默认跟踪。
回购. ex
这是我们更新的回购模块:
斯洛格。埃克托
当这个模块被repo.ex使用时，一个新的模块YourApp.Repo.SlowLogger被动态创建。多么 meta！这个模块包装了像query、all和update这样的 Ecto 查询函数。我们就能确定他们的执行时间并追踪他们的行踪。
这是实现的肉。这里是模块源码。让我们走一遍。
我们如何覆盖 Ecto 函数？
技术上来说，我们不能。只有通过[defoverridable](https://hexdocs.pm/elixir/Kernel.html#defoverridable/1)关键字引用的 Elixir 函数才能被直接覆盖。运行查询的 Ecto 函数——all、query、update等——没有被列为可重写的。
我们可以解决这个问题。我们将动态创建一个新模块。这个模块包含在我们的Repo模块中，我们将定义函数来包装对像unquote(__MODULE__).query(a)一样需要它的模块的调用。
**Module.__using__/1**
当在repo.ex内部调用[use](http://www.zohaib.me/use-in-elixir-explained/)宏时，调用该函数。通常这样做是为了在调用模块内部注入函数(YourApp.Repo)，在这种情况下，代码会创建一个完整的子模块。
`[quote](http://elixir-lang.org/getting-started/meta/quote-and-unquote.html)`宏****
我们已经定义了希望在双重嵌套的quote块中跟踪慢速查询的 Ecto 函数。外部的quote块通过use放在调用模块中。内部引用块包含分配给一个content变量的函数定义。quote块生成一段独立的代码:它不会立即执行。
`__trace/1`
这将进行实际的跟踪:我们记录 start_time，调用函数，并记录 end_time。
`Module.create/3`
Module.create(slow_logger_repo_module, contents, __ENV__)
这将从内部的quote块中获取内容，并创建我们的新模块来跟踪我们的回购查询。我们将使用这个模块来运行 Ecto 查询。
web.ex
我们将在web.ex中为动态创建的模块YourApp.Repo.SlowLogger起别名，这样我们对Repo的调用就通过我们的跟踪来路由:
嘣！痕迹！
我们现在记录对缓慢的 Ecto 函数调用的跟踪。
我可以同时拥有原始 SQL 和回溯吗？
此时，我们知道如何:
- 记录慢速查询的原始 SQL
- 记录对慢速 Ecto 函数调用的回溯
我们没有把它们结合在一起:既看到慢速查询的原始 SQL，又看到其源代码位置的相关回溯给出了完整的画面。
处理/放置和处理/获取
我们的结婚戒指将成为长生不老药的过程字典。将日志条目存储在流程字典中，并从我们的跟踪逻辑中获取它。
在我们的 Ecto logger 中，我们将把日志条目放在进程字典中:
…并获取__trace/1中的日志条目:
log_entry = Process.get(:ecto_log_entry)
嘣！我们什么都有了:
TL；速度三角形定位法(dead reckoning)
以下是记录慢速 Ecto 查询的说明:
- 将
web.ex中的回购别名更改为YourApp.Repo.SlowLogger。 - 将
Ecto记录器添加到config.exs:
config :yourapp, YourApp.Repo,
loggers: [{Ecto.LogEntry, :log, []}, {Ecto.LogTrace, :trace, []}]3.将[SlowLogger.Ecto](https://gist.github.com/itsderek23/f83a3f24d9a417c87da4993e8ce9db48)放到你的lib/文件夹中。
4.将[Ecto.LogTrace](https://gist.github.com/itsderek23/03c29bd3077b6e17a43f5233221eb8b3)放到你的lib/文件夹中。
5.将下面一行添加到您的repo.ex文件中:use SlowLogger.Ecto.
PSA:咻…太多的步骤？我们正在构建 Elixir 应用程序监控，它将在我的日常工作中为你完成大部分工作。 [报名提前接入](https://apm.scoutapp.com/elixir) 。
**
**
