Benchmark serializer attributes caching

ref:
- rails-api#827
- rails-api#832
- rails-api#872
- rails-api#1045
- rails-api#912
- rails-api#911
- rails-api#904
- rails-api#810
- rails-api#693
- rails-api#849
- rails-api#1029
- rails-api#1300
- rails-api#1372

Gemfile

@@ -36,6 +36,10 @@ end
 # Windows does not include zoneinfo files, so bundle the tzinfo-data gem
 gem 'tzinfo-data', platforms: (@windows_platforms + [:jruby])
 
+group :development do
+  gem 'benchmark-ips'
+end
+
 group :test do
   gem 'sqlite3',                          platform: (@windows_platforms + [:ruby])
   gem 'activerecord-jdbcsqlite3-adapter', platform: :jruby

bench/perf.rb

@@ -1,40 +1,177 @@
-require 'rubygems'
+require "pathname"
+ams_dir = Pathname File.expand_path(['..', '..'].join(File::Separator), __FILE__)
+LIB_PATH = ams_dir.join("lib")
+# Use absolute path so we can run benchmark in tempdir
+$LOAD_PATH.unshift(LIB_PATH.to_s)
 require 'bundler/setup'
-require 'rails/railtie'
-require 'active_model_serializers'
+require 'rails'
+require 'action_controller'
+require 'action_controller/test_case'
+require 'action_controller/railtie'
 require 'active_support/json'
-require 'benchmark'
-
-class User < Struct.new(:id, :name, :age, :about)
-  include ActiveModel::Serialization
-
-  def fast_hash
-    h = {
-      id: read_attribute_for_serialization(:id),
-      name: read_attribute_for_serialization(:name),
-      about: read_attribute_for_serialization(:about)
-    }
-    h[:age] = read_attribute_for_serialization(:age) if age > 18
-    h
+ActionController::Base.cache_store = :memory_store
+require 'active_model_serializers'
+ActiveModel::Serializer.config.cache_store ||= ActiveSupport::Cache.lookup_store(ActionController::Base.cache_store || Rails.cache || :memory_store)
+require 'benchmark/ips'
+
+module Benchmarking
+  class Comment < ActiveModelSerializers::Model
+    attr_accessor :id, :body
+
+    def cache_key
+      "#{self.class.name.downcase}/#{self.id}"
+    end
   end
-end
+  class Author < ActiveModelSerializers::Model
+    attr_accessor :id, :name
+  end
+  class Post < ActiveModelSerializers::Model
+    attr_accessor :id, :title, :blog, :body, :comments, :author
+    def cache_key
+      "benchmarking::post/1-20151215212620000000000"
+    end
+  end
+  class Blog < ActiveModelSerializers::Model
+    attr_accessor :id, :name
+  end
+  class PostSerializer < ActiveModel::Serializer
+    cache key: 'post', expires_in: 0.1, skip_digest: true
+    attributes :id, :title, :body
+
+    has_many :comments
+    belongs_to :blog
+    belongs_to :author
 
-class UserSerializer < ActiveModel::Serializer
-  attributes :id, :name, :age, :about
+    def blog
+      Blog.new(id: 999, name: 'Custom blog')
+    end
+    class CommentSerializer < ActiveModel::Serializer
+      cache expires_in: 1.day, skip_digest: true
+      attributes :id, :body
 
-  def include_age?
-    object.age > 18
+      belongs_to :post
+      belongs_to :author
+    end
+    class AuthorSerializer < ActiveModel::Serializer
+      cache key: 'writer', skip_digest: true
+      attribute :id
+      attribute :name
+
+      has_many :posts
+    end
+    class BlogSerializer < ActiveModel::Serializer
+      cache key: 'blog'
+      attributes :id, :name
+    end
   end
 end
 
-u = User.new(1, 'sam', 10, 'about')
-s = UserSerializer.new(u)
 
-n = 100000
+comment = Benchmarking::Comment.new({ id: 1, body: 'ZOMG A COMMENT' })
+author  = Benchmarking::Author.new(id: 1, name: 'Joao Moura.')
+post    = Benchmarking::Post.new({ id: 1, title: 'New Post', blog:nil, body: 'Body', comments: [comment], author: author })
+serializer = Benchmarking::PostSerializer.new(post)
+serialization = ActiveModel::SerializableResource.new(post, serializer: Benchmarking::PostSerializer, adapter: :attributes)
+expected_attributes = {
+  id: 1,
+  title: 'New Post',
+  body: 'Body',
+}
+expected_associations = {
+  comments: [
+    {
+      id: 1,
+      body: 'ZOMG A COMMENT' }
+  ],
+  blog: {
+    id: 999,
+    name: 'Custom blog'
+  },
+  author: {
+    id: 1,
+    name: 'Joao Moura.'
+  }
+}
+expected = expected_attributes.merge(expected_associations)
+p [serializer.attributes, expected_attributes].tap {|a| a.unshift(a[0] == a[1]) }
+p [serializer.class._cache, ActionController::Base.cache_store].tap {|a| a.unshift(a[0] == a[1]) }
+p [serializer.class._cache_options, {expires_in: 0.1, skip_digest: true }].tap {|a| a.unshift(a[0] == a[1]) }
+p [serializer.class._cache_key, post.cache_key] #.tap {|a| a.unshift(a[0] == a[1]) }
+p [serialization.serializable_hash, ActiveModel::Serializer.config.cache_store.fetch(post.cache_key)].tap {|a| a.unshift(a[0] == a[1]) }
+p [serializer.class._cache_digest, Digest::MD5.hexdigest(IO.read(__FILE__))].tap {|a| a.unshift(a[0] == a[1]) }
+p [serializer.class._cache_only]
+p [serializer.class._cache_except]
+p [serialization.serializable_hash, expected].tap {|a| a.unshift(a[0] == a[1]) }
+define_method(:cache_on) do |caching_on|
+  ActiveModel::Serializer.config.cache_store.clear
+  ActiveModel::Serializer.config.perform_caching = caching_on
+end
+define_method(:run_example_code) do
+  attributes = serializer.attributes
+  attributes == expected_attributes or fail "#{attributes} isn't equal to #{expected}"
+# -> { attributes = serializer.attributes == expected
+end
+define_method(:after_run) do
+  # p ActiveModel::Serializer.config.cache_store
+end
+require "benchmark/ips"
+puts "Running Benchmark.ips"
+reports = Benchmark.ips do |x|
+  # the warmup phase (default 2) and calculation phase (default 5)
+  x.config(time: 5, warmup: 2)
 
-Benchmark.bmbm do|x|
-  x.report('init') { n.times { UserSerializer.new(u) } }
-  x.report('fast_hash') { n.times { u.fast_hash } }
-  x.report('attributes') { n.times { UserSerializer.new(u).attributes } }
-  # x.report("serializable_hash") { n.times { u.serializable_hash } }
+  x.report("caching")  do |times|
+    Process.waitpid2(fork do
+      cache_on(true)
+      i = 0
+      while i < times
+        run_example_code
+        i += 1
+      end
+    end)
+    after_run
+  end
+
+  x.report("no caching")  do |times|
+    Process.waitpid2(fork do
+      cache_on(false)
+      i = 0
+      while i < times
+        run_example_code
+        i += 1
+      end
+    end)
+    after_run
+  end
+
+  x.compare!
 end
+# https://github.com/rails-api/active_model_serializers/pull/810#issuecomment-89870165
+# Update: here are the numbers I got:
+#
+#                user        system    total     real
+# no cache       21.550000   1.820000  23.370000 ( 28.894494)
+# cache          16.870000   1.580000  18.450000 ( 21.429540)
+# fragment cache 22.270000   1.810000  24.080000 ( 28.504920)
+#
+# (cache means `only: []` wasn't used in the serializer)
+
+# https://github.com/rails-api/active_model_serializers/pull/810#issuecomment-94940858
+#
+# # both fragment
+# cache only: [:field1, :field2, :etc]
+#
+# # and not fragment
+# cache
+#
+# # then, in an integration test:
+# Benchmark.bm do |x|
+#   x.report do
+#     1000.times do
+#       get "/users/#{user.id}", nil
+#     end
+#   end
+# end
+#
+#
+exit 0

bin/run-command-on-git-revisions

@@ -0,0 +1,86 @@
+#!/bin/bash
+#
+# This script runs a given command over a range of Git revisions. Note that it
+# will check past revisions out! Exercise caution if there are important
+# untracked files in your working tree.
+#
+# This came from Gary Bernhardt's dotfiles:
+#     https://github.com/garybernhardt/dotfiles
+#     https://github.com/garybernhardt/dotfiles/blob/9ffa83887/bin/run-command-on-git-revisions
+#
+# Example usage:
+#     $ run-command-on-git-revisions origin/master master 'python runtests.py'
+
+set -e
+
+if [[ $1 == -v ]]; then
+    verbose=1
+    shift
+fi
+
+start_ref=$1
+end_ref=$2
+test_command=$3
+
+main() {
+    abort_if_dirty_repo
+    enforce_usage
+    run_tests
+}
+
+abort_if_dirty_repo() {
+    set +e
+    git diff-index --quiet --cached HEAD
+    if [[ $? -ne 0 ]]; then
+        echo "You have staged but not committed changes that would be lost! Aborting."
+        exit 1
+    fi
+    git diff-files --quiet
+    if [[ $? -ne 0 ]]; then
+        echo "You have unstaged changes that would be lost! Aborting."
+        exit 1
+    fi
+    untracked=$(git ls-files --exclude-standard --others)
+    if [ -n "$untracked" ]; then
+        echo "You have untracked files that could be overwritten! Aborting."
+        exit 1
+    fi
+    set -e
+}
+
+enforce_usage() {
+    if [ -z "$test_command" ]; then
+        usage
+        exit $E_BADARGS
+    fi
+}
+
+usage() {
+    echo "usage: `basename $0` start_ref end_ref test_command"
+}
+
+run_tests() {
+    revs=`log_command git rev-list --reverse ${start_ref}..${end_ref}`
+
+    for rev in $revs; do
+        debug "Checking out: $(git log --oneline -1 $rev)"
+        log_command git checkout --quiet $rev
+        log_command $test_command
+        log_command git reset --hard --quiet
+    done
+    log_command git checkout --quiet $end_ref
+    debug "OK for all revisions!"
+}
+
+log_command() {
+    debug "=> $*"
+    eval "$@"
+}
+
+debug() {
+    if [ $verbose ]; then
+        echo $* >&2
+    fi
+}
+
+main

bin/run-ruby-file-on-git-revisions

@@ -0,0 +1,68 @@
+#!/usr/bin/env ruby
+
+ENV['AMS_DIR'] = File.expand_path(['..', '..'].join(File::Separator), __FILE__)
+# usage:
+# bin/run-ruby-file-on-git-revisions start_rev end_rev path/to/ruby_file.rb
+# example:
+# bin/run-ruby-file-on-git-revisions 38a62b1eae357^ cache_fix bench/perf.rb
+require 'pty'
+# should consider trapping SIGINT in here
+def run(cmd)
+  puts cmd
+  child_process = ''
+  result = ''
+  # http://stackoverflow.com/a/1162850
+  # stream output of subprocess
+  begin
+    PTY.spawn(cmd) do |stdin, _stdout, pid|
+      begin
+        # Do stuff with the output here. Just printing to show it works
+        stdin.each do |line|
+          print line
+          result << line
+        end
+        child_process = PTY.check(pid)
+      rescue Errno::EIO
+        puts 'Errno:EIO error, but this probably just means ' \
+              'that the process has finished giving output'
+      end
+    end
+  rescue PTY::ChildExited
+    puts 'The child process exited!'
+  end
+  unless child_process.success?
+    exitstatus = child_process.exitstatus
+    puts "FAILED: #{child_process.pid} exited with status #{exitstatus.inspect} due to failed command #{cmd}"
+    exit exitstatus || 1
+  end
+  result
+end
+
+args = ARGV.to_a
+if args.size != 3
+  fail 'expecting three arguments: start_rev end_rev path_to_ruby_file'
+end
+(start_rev, end_rev, ruby_file_path) = args
+fail "#{ruby_file_path} not readable" unless File.readable?(ruby_file_path)
+
+require 'tempfile'
+require 'fileutils'
+
+tmp_file_name = ruby_file_path.gsub(/[\/\.]/, '_')
+Tempfile.open('log') do |log_file|
+  file = Tempfile.new(tmp_file_name)
+  begin
+    file.write File.read(ruby_file_path)
+    file.close
+    run '$AMS_DIR/bin/run-command-on-git-revisions -v '\
+      "%s %s 'ruby %s' 2>&1 | tee %s" %
+      [start_rev, end_rev, file.path, log_file.path]
+  ensure
+    file.close unless file.closed?
+    file.unlink   # deletes the temp file
+  end
+
+  new_log_file_path = "/tmp/#{tmp_file_name}.log"
+  FileUtils.cp(log_file.path, new_log_file_path)
+  puts "Log file is at #{new_log_file_path}"
+end