Active Model Serializer 10 caching. It doesn't seem to be working. Why?

Question

My toy app has a couple of models, rental_units and users. You can find the repo here

I am running Rails 5 and AMS 10.

active_model_serializers (0.10.0.rc4)
...
rails (5.0.0.beta3)
      actioncable (= 5.0.0.beta3)
      actionmailer (= 5.0.0.beta3)
      actionpack (= 5.0.0.beta3)
...

I have a RentalUnitSerializer that looks like this:

class RentalUnitSerializer < ActiveModel::Serializer
  cache key: 'rental_unit', expires_in: 3.hours
  attributes :id, :rooms, :bathrooms, :price, :price_cents

  belongs_to :user
end

This is my UserSerializer:

class UserSerializer < ActiveModel::Serializer
  cache key: 'user'
  attributes :id, :name, :email
  has_many :rental_units

  def name
    names = object.name.split(" ")
    "#{names[0].first}. #{names[1]}"
  end
end

This is part of my Gemfile:

    source 'https://rubygems.org'

# Bundle edge Rails instead: gem 'rails', github: 'rails/rails'
gem 'rails', '>= 5.0.0.beta3', '< 5.1'
# Use sqlite3 as the database for Active Record
gem 'sqlite3'
# Use Puma as the app server
gem 'puma'
gem 'active_model_serializers', '~> 0.10.0.rc1'
gem "dalli"
gem "memcachier"

And this is my config/environments/development.rb file:

Rails.application.configure do
  # Settings specified here will take precedence over those in config/application.rb.

  # In the development environment your application's code is reloaded on
  # every request. This slows down response time but is perfect for development
  # since you don't have to restart the web server when you make code changes.
  config.cache_classes = false

  # Do not eager load code on boot.
  config.eager_load = false

  # Show full error reports.
  config.consider_all_requests_local = true

  # Enable/disable caching. By default caching is disabled.
  if Rails.root.join('tmp/caching-dev.txt').exist?
    config.action_controller.perform_caching = true

    config.action_mailer.perform_caching = false

    config.cache_store = :memory_store
    config.public_file_server.headers = {
      'Cache-Control' => 'public, max-age=172800'
    }
  else
    config.action_controller.perform_caching = true

    config.action_mailer.perform_caching = false

    config.cache_store = :memory_store
  end

  # Don't care if the mailer can't send.
  config.action_mailer.raise_delivery_errors = false

  # Print deprecation notices to the Rails logger.
  config.active_support.deprecation = :log

  # Raise an error on page load if there are pending migrations.
  config.active_record.migration_error = :page_load


  # Raises error for missing translations
  # config.action_view.raise_on_missing_translations = true

  # Use an evented file watcher to asynchronously detect changes in source code,
  # routes, locales, etc. This feature depends on the listen gem.
  config.file_watcher = ActiveSupport::EventedFileUpdateChecker
end

Here is the strange behavior

When I visit http://localhost:3000/users, this is my logs with no sign of caching:

Started GET "/users" for ::1 at 2016-03-04 15:18:12 -0500
Processing by UsersController#index as HTML
  User Load (0.1ms)  SELECT "users".* FROM "users"
[active_model_serializers]   RentalUnit Load (0.2ms)  SELECT "rental_units".* FROM "rental_units" WHERE "rental_units"."user_id" = ?  [["user_id", 1]]
[active_model_serializers]   RentalUnit Load (0.1ms)  SELECT "rental_units".* FROM "rental_units" WHERE "rental_units"."user_id" = ?  [["user_id", 2]]
[active_model_serializers]   RentalUnit Load (0.1ms)  SELECT "rental_units".* FROM "rental_units" WHERE "rental_units"."user_id" = ?  [["user_id", 3]]
[active_model_serializers] Rendered ActiveModel::Serializer::CollectionSerializer with ActiveModel::Serializer::Adapter::JsonApi (11.0ms)
Completed 200 OK in 13ms (Views: 12.5ms | ActiveRecord: 0.5ms)

When I visit http://localhost:3000/rental_units, there is some caching?

Started GET "/rental_units" for ::1 at 2016-03-04 15:18:37 -0500
Processing by RentalUnitsController#index as HTML
  RentalUnit Load (0.4ms)  SELECT "rental_units".* FROM "rental_units"
[active_model_serializers]   User Load (0.9ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 1], ["LIMIT", 1]]
[active_model_serializers]   CACHE (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 1], ["LIMIT", 1]]
[active_model_serializers]   CACHE (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 1], ["LIMIT", 1]]
[active_model_serializers]   User Load (0.1ms)  SELECT  "users".* FROM "users" WHERE "users"."id" = ? LIMIT ?  [["id", 2], ["LIMIT", 1]]
[active_model_serializers] Rendered ActiveModel::Serializer::CollectionSerializer with ActiveModel::Serializer::Adapter::JsonApi (16.1ms)
Completed 200 OK in 21ms (Views: 19.1ms | ActiveRecord: 1.4ms)

What is going on? It looks like in the latter logs, the users are being cached? I believe that since 3 different rental units belong to User 1, AMS has some default caching going on where identical SQL queries just hit a cache of some kind. So the first query for User1 hits the server's database but subsequent queries for User1 do not. Where is this cache? Is it on the server? Or some webserver?

But I think my caching strategy in my Serializer isn't working at all. Why?

Answer 1

To help with debugging, try setting a logger for your cache. The Rails cache supports setting a logger, but the MemoryStore doesn't set it by default.

In an initializer, try the following:

# config/initializers/cache.rb
Rails.cache.logger = Logger.new(STDOUT)
# or Rails.cache.logger = Rails.logger

Restart your Rails server and you should see logging of cache hits/misses. I suspect it is working but possibly not in a way you were expecting.

---

Since you asked, there's actually a couple layers of caching your question touches on: fragment (or view) caching and query caching.

You've enabled the cache as :memory_store which will create an instance of ActiveSupport::Cache::MemoryStore accessible in your application and in the Rails console as Rails.cache.

You've also set cache options for your serializer. From the ActiveModelSerializer guides for your version, it looks like you've set this up correctly. So far so good.

Typically, in a Rails controller, the Rails cache doesn't get invoked until you go to render a view. In your case, you're rendering a json view (through AMS); it'd work the same with an HTML template.

The first time this request is made, the cache is cold, the DB query is made, Rails asks the cache for a representation of the JSON string(s) using a cache key (or keys). Since the cache is empty for this set of resources, the JSON string must be generated, then it is cached in Rails.cache, then the response is returned.

The next time this request is made (within the expiration window), the DB query is made - Rails needs to know what for which resources to ask the cache right? - and this time, the cache hits, and the string is returned from cache. No new JSON needs to be generated. Notice that this still incurs a DB hit to request the original resource(s). These requests are necessary for AMS to look up the cache key(s) for your JSON.

You're also seeing CACHE select ... queries in your logs as well. As was mentioned in another answer, this may indicate you're making the same DB query over and over (often an indication of an N+1 query), hence the suggestion to "eager load" those relations. Your RentalUnit belongs to :user, so for each rental unit, a separate request is being made for each user - you may be able to grab all those users in one query with eager loading.

Rails provides some ability to cache the results of SQL queries. This is separate from the view caching we've been discussing which you've enabled for AMS.