生产环境下ActiveRecord的`includes`未缓存数据

Question

我正在使用Rails 4.2和Heroku。

我理解ActiveRecord的includes函数是一次性获取所有相关数据，因此当您调用关系时，它不必再执行额外的查询。

我看到它正在获取相关数据，但在生产环境（在Heroku上）中，每次调用关系时，我也看到它再次获取数据。为什么会这样，我该如何解决？

这只在生产环境中发生，而不是在开发环境中。

这是我观察到的函数：

  def max_outcome_scores()
    scores = Hash.new(0)
    logger.info '*** Running max_outcome_score ***'
    language_progresses.with_updates.
        includes(:progress_marker).find_each do |progress|
      scores[progress.progress_marker.topic_id] += progress.progress_marker.weight  * ProgressMarker.spread_text.keys.max
    end
    logger.info '*** Finished max_outcome_score ***'
    return scores
  end

该函数按预期工作，但是查询数据库的次数太多了。日志中显示如下：

2016-07-13T06:55:30.304893+00:00 app[web.1]: *** Running max_outcome_score ***
2016-07-13T06:55:30.308102+00:00 app[web.1]:   LanguageProgress Load (2.4ms)  SELECT  "language_progresses".* FROM "language_progresses" INNER JOIN "progress_updates" ON "progress_updates"."language_progress_id" = "language_progresses"."id" WHERE "language_progresses"."state_language_id" = $1  ORDER BY "language_progresses"."id" ASC LIMIT 1000  [["state_language_id", 209]]
2016-07-13T06:55:30.308882+00:00 app[web.1]:   ↳ app/models/state_language.rb:104:in `max_outcome_scores'
2016-07-13T06:55:30.313090+00:00 app[web.1]:   CACHE (0.0ms)  SELECT "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" IN (70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 130, 80, 81, 82, 98, 99, 100, 101, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 83, 84, 85, 86, 87, 88, 90, 91, 92, 93, 94, 131, 89, 95, 96, 97, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129)
2016-07-13T06:55:30.314067+00:00 app[web.1]:   ↳ app/models/state_language.rb:104:in `max_outcome_scores'
2016-07-13T06:55:30.317657+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 71]]
2016-07-13T06:55:30.318379+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.318730+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 71]]
2016-07-13T06:55:30.319448+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.319872+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 75]]
2016-07-13T06:55:30.320580+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.320953+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 77]]
2016-07-13T06:55:30.321671+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.322226+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 103]]
2016-07-13T06:55:30.322938+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.323543+00:00 app[web.1]:   CACHE (0.0ms)  SELECT  "progress_markers".* FROM "progress_markers" WHERE "progress_markers"."id" = $1 LIMIT 1  [["id", 60]]
2016-07-13T06:55:30.324251+00:00 app[web.1]:   ↳ app/models/state_language.rb:105:in `block in max_outcome_scores'
2016-07-13T06:55:30.324966+00:00 app[web.1]: *** Finished max_outcome_score ***

我已经配置了日志，输出生成查询的代码行。第104行是带有includes的行，第105行是在find-each块内的行。

- Toby 1 Kenobi

---

这是否意味着它从缓存中获取并且花费了0秒钟的时间？ CACHE（0.0毫秒） - Taryn East

可能吧！但为什么它被表达成一个SQL查询呢？看起来像是在访问数据库？ - Toby 1 Kenobi

好问题 - 我也想知道答案... :D 只是可能并不像一开始想象的那么糟糕... - Taryn East

也许Heroku选择绕过ActiveRecord的缓存并拦截自己的查询。 - Toby 1 Kenobi

如果有人能在答案中确认那个理论，我会接受那个答案。 - Toby 1 Kenobi

通常情况下，如果您预加载记录，则不会有查询（也没有CACHE查询）。您能展示一下您的模型代码吗？ - siegy22

Answer 1

原来，即使ActiveRecord事先收集了所有必要的数据，当它被要求提供本应该需要从数据库获取的数据时，它仍然构建相关查询，但不是向数据库发送请求，而是直接从缓存中提取数据。然后，它记录了它构建的查询，但没有在数据库上使用。

在某些情况下，查看这些查询可能有助于测试和调试，但大多数时候我发现它们只会堵塞日志。

Raphael提供了一种抑制此日志记录的方法。将此代码放入config/initializers中的一个Ruby文件中。

# Create logger that ignores messages containing “CACHE”
class CacheFreeLogger < ::Logger
  def debug(message, *args, &block)
    super unless message.include? 'CACHE'
  end
end

# Overwrite ActiveRecord’s logger
ActiveRecord::Base.logger = ActiveSupport::TaggedLogging.new(
  CacheFreeLogger.new(STDOUT)) unless Rails.env.test?

- Toby 1 Kenobi