{"action":"created","issue":{"url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/1586","repository_url":"https://api.github.com/repos/rails-api/active_model_serializers","labels_url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/1586/labels{/name}","comments_url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/1586/comments","events_url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/1586/events","html_url":"https://github.com/rails-api/active_model_serializers/issues/1586","id":140454193,"number":1586,"title":"Caching doesn't improve performance","user":{"login":"bf4","id":142914,"avatar_url":"https://avatars1.githubusercontent.com/u/142914?v=3","gravatar_id":"","url":"https://api.github.com/users/bf4","html_url":"https://github.com/bf4","followers_url":"https://api.github.com/users/bf4/followers","following_url":"https://api.github.com/users/bf4/following{/other_user}","gists_url":"https://api.github.com/users/bf4/gists{/gist_id}","starred_url":"https://api.github.com/users/bf4/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bf4/subscriptions","organizations_url":"https://api.github.com/users/bf4/orgs","repos_url":"https://api.github.com/users/bf4/repos","events_url":"https://api.github.com/users/bf4/events{/privacy}","received_events_url":"https://api.github.com/users/bf4/received_events","type":"User","site_admin":false},"labels":[{"id":184617600,"url":"https://api.github.com/repos/rails-api/active_model_serializers/labels/C:%20Documentation","name":"C: Documentation","color":"fbca04","default":false},{"id":319962109,"url":"https://api.github.com/repos/rails-api/active_model_serializers/labels/C:%20Performance:%20Caching","name":"C: Performance: Caching","color":"CCCCCC","default":false},{"id":123839649,"url":"https://api.github.com/repos/rails-api/active_model_serializers/labels/S:%20Bug","name":"S: Bug","color":"e11d21","default":false},{"id":184618099,"url":"https://api.github.com/repos/rails-api/active_model_serializers/labels/S:%20Ready%20for%20PR","name":"S: Ready for PR","color":"009800","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":{"url":"https://api.github.com/repos/rails-api/active_model_serializers/milestones/5","html_url":"https://github.com/rails-api/active_model_serializers/milestone/5","labels_url":"https://api.github.com/repos/rails-api/active_model_serializers/milestones/5/labels","id":1011188,"number":5,"title":"0.10","description":"","creator":{"login":"kurko","id":70312,"avatar_url":"https://avatars0.githubusercontent.com/u/70312?v=3","gravatar_id":"","url":"https://api.github.com/users/kurko","html_url":"https://github.com/kurko","followers_url":"https://api.github.com/users/kurko/followers","following_url":"https://api.github.com/users/kurko/following{/other_user}","gists_url":"https://api.github.com/users/kurko/gists{/gist_id}","starred_url":"https://api.github.com/users/kurko/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kurko/subscriptions","organizations_url":"https://api.github.com/users/kurko/orgs","repos_url":"https://api.github.com/users/kurko/repos","events_url":"https://api.github.com/users/kurko/events{/privacy}","received_events_url":"https://api.github.com/users/kurko/received_events","type":"User","site_admin":false},"open_issues":23,"closed_issues":81,"state":"open","created_at":"2015-03-08T13:22:14Z","updated_at":"2017-03-12T19:32:22Z","due_on":"2015-11-15T08:00:00Z","closed_at":null},"comments":16,"created_at":"2016-03-13T06:19:16Z","updated_at":"2017-04-03T22:03:23Z","closed_at":null,"body":"#### Expected behavior vs actual behavior\n\nExpected: Configure a cache and using the AMS serializer cache method should improve rendering performance.\n\nActual: performance decreases AND more objects are allocated.\n#### Steps to reproduce\n\ncurrent master: `git co fa0bc95`.\n\n``` plain\n bin/bench\ncaching on: caching serializers: gc off 606.0970710386515/ips; 1853 objects\ncaching off: caching serializers: gc off 526.5338285238549/ips; 1853 objects\ncaching on: non-caching serializers: gc off 709.8031139840541/ips; 1390 objects\ncaching off: non-caching serializers: gc off 746.4513428127035/ips; 1390 objects\nBenchmark results:\n{\n  \"commit_hash\": \"fa0bc95\",\n  \"version\": \"0.10.0.rc4\",\n  \"benchmark_run[environment]\": \"2.2.3p173\",\n  \"runs\": [\n    {\n      \"benchmark_type[category]\": \"caching on: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 606.097,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1853\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 526.534,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1853\n    },\n    {\n      \"benchmark_type[category]\": \"caching on: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 709.803,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1390\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 746.451,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1390\n    }\n  ]\n}\n```\n\n```\nCACHE_ON=false bin/bench\ncaching on: caching serializers: gc off 664.8712562099971/ips; 1853 objects\ncaching off: caching serializers: gc off 613.6203762167032/ips; 1853 objects\ncaching on: non-caching serializers: gc off 752.267454951568/ips; 1390 objects\ncaching off: non-caching serializers: gc off 692.4981276214933/ips; 1390 objects\nBenchmark results:\n{\n  \"commit_hash\": \"fa0bc95\",\n  \"version\": \"0.10.0.rc4\",\n  \"benchmark_run[environment]\": \"2.2.3p173\",\n  \"runs\": [\n    {\n      \"benchmark_type[category]\": \"caching on: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 664.871,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1853\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 613.62,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1853\n    },\n    {\n      \"benchmark_type[category]\": \"caching on: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 752.267,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1390\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 692.498,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1390\n    }\n  ]\n}\n```\n\nNumber vary somewhat over runs but differences are consistent.\n#### Environment\n- ActiveModelSerializers Version\n  `0.10.0.rc4`, on ref `fa0bc95`\n- `ruby -e \"puts RUBY_DESCRIPTION\"`\n  - `ruby 2.2.3p173 (2015-08-18 revision 51636) [x86_64-darwin14]`\n\nOS Type & Version: \n- `uname -a`\n  - `Darwin mbp14 14.5.0 Darwin Kernel Version 14.5.0: Tue Sep  1 21:23:09 PDT 2015; root:xnu-2782.50.1~1/RELEASE_X86_64 x86_64`: Yosemite 10.10.15\n    Integrated application and version \n- `bundle show activemodel`\n  - `.bundle/ruby/2.2.0/gems/activemodel-4.0.13`\n#### Backtrace\n\nN/A\n#### Additional helpful information\n- https://blog.codeship.com/building-a-json-api-with-rails-5/\n  - > By making these changes, we’ve changed our response time from 30ms to 50ms… wait, what? Yes, you heard me right. By adding cache, responses in my application have actually slowed down.\n  - https://twitter.com/leighchalliday/status/642734572703236096 and https://twitter.com/joaomdmoura/status/642801896231727104\n    - <img width=\"520\" alt=\"screen shot 2016-03-12 at 11 53 11 pm\" src=\"https://cloud.githubusercontent.com/assets/142914/13727183/b1fe2836-e8ad-11e5-8922-f58c05646dae.png\">\n  - > By looking at the flame graph with caching turned on, I could tell that 48 percent of the time was spent in the cache_check method or farther down in the stack trace. This seems to account for the slowdown from 30ms to 50ms.\n    > `active_model_serializers-258f116c3cf5/lib/active_model/serializer/adapter.rb:110:in`cache_check'`  (48 samples - 48.00%)\n    > Here’s an image of the flamegraph, which was produced by using rack mini profiler gem with the flamegraph gem. I’ve highlighted in black the portion that’s dealing with the cache.\n    > ![flame-graph-with-cache-with-box](https://cloud.githubusercontent.com/assets/142914/13727196/2e535c12-e8ae-11e5-8216-d2fc0811a32f.jpg)\n\nCache developments since then:\n- We now [support read_multi](https://github.com/rails-api/active_model_serializers/pull/1372)\n\nHowever:\n- before:\n\n``` json\n{\n  \"commit_hash\": \"43312fa^\",\n  \"version\": \"0.10.0.rc3\",\n  \"benchmark_run[environment]\": \"2.2.2p95\",\n  \"runs\": [\n    {\n      \"benchmark_type[category]\": \"caching on: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 687.045,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1426\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 688.588,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1426\n    },\n    {\n      \"benchmark_type[category]\": \"caching on: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 849.889,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1084\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 769.596,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1084\n    }\n  ]\n}\n```\n- after:\n\n``` json\n{\n  \"commit_hash\": \"43312fa\",\n  \"version\": \"0.10.0.rc3\",\n  \"benchmark_run[environment]\": \"2.2.2p95\",\n  \"runs\": [\n    {\n      \"benchmark_type[category]\": \"caching on: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 635.297,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1519\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 601.3,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1519\n    },\n    {\n      \"benchmark_type[category]\": \"caching on: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 782.07,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1113\n    },\n    {\n      \"benchmark_type[category]\": \"caching off: non-caching serializers: gc off\",\n      \"benchmark_run[result][iterations_per_second]\": 771.094,\n      \"benchmark_run[result][total_allocated_objects_per_iteration]\": 1113\n    }\n  ]\n}\n```\n\nSo maybe we should take a look at [usage in bulk_cache_fetcher](https://github.com/justinweiss/bulk_cache_fetcher/blob/df1c83e06b9641b7ec3408ec577b37528021190f/lib/bulk_cache_fetcher.rb)\n\nAnd with more objects it gets worse:\n\n> BENCH_STRESS=true bin/bench\n> Benchmark results:\n> \n> ``` json\n> {\n>   \"commit_hash\": \"e03c5f5\",\n>   \"version\": \"0.10.0.rc4\",\n>   \"benchmark_run[environment]\": \"2.2.3p173\",\n>   \"runs\": [\n>     {\n>       \"benchmark_type[category]\": \"caching on: caching serializers: gc off\",\n>       \"benchmark_run[result][iterations_per_second]\": 164.688,\n>       \"benchmark_run[result][total_allocated_objects_per_iteration]\": 10755\n>     },\n>     {\n>       \"benchmark_type[category]\": \"caching off: caching serializers: gc off\",\n>       \"benchmark_run[result][iterations_per_second]\": 143.719,\n>       \"benchmark_run[result][total_allocated_objects_per_iteration]\": 10755\n>     },\n>     {\n>       \"benchmark_type[category]\": \"caching on: non-caching serializers: gc off\",\n>       \"benchmark_run[result][iterations_per_second]\": 232.669,\n>       \"benchmark_run[result][total_allocated_objects_per_iteration]\": 6690\n>     },\n>     {\n>       \"benchmark_type[category]\": \"caching off: non-caching serializers: gc off\",\n>       \"benchmark_run[result][iterations_per_second]\": 211.71,\n>       \"benchmark_run[result][total_allocated_objects_per_iteration]\": 6690\n>     }\n>   ]\n> }\n> ```\n\nPossibly related\n- [Cache not working](https://github.com/rails-api/active_model_serializers/issues/923)\n- [Modify cache key to prevent errors and incorrect data returned. Fixes #1344](https://github.com/rails-api/active_model_serializers/pull/1346)\n- [Trigger callback to set serializer#_cache when controller loaded](https://github.com/rails-api/active_model_serializers/pull/1478)\n\nFlamegraph\n- Flamegraph of master with `bin/serve_benchmark start` and the flamegraph gem\n  - ![screen shot 2016-03-09 at 9 34 21 pm](https://cloud.githubusercontent.com/assets/142914/13727231/21c0ffb6-e8b0-11e5-8067-8130b85bce5f.png)\n\n``` diff\niff --git a/Gemfile b/Gemfile\nindex 3791eef..7be3d53 100644\n--- a/Gemfile\n+++ b/Gemfile\n@@ -39,6 +39,8 @@ gem 'tzinfo-data', platforms: (@windows_platforms + [:jruby])\n group :bench do\n   # https://github.com/rails-api/active_model_serializers/commit/cb4459580a6f4f37f629bf3185a5224c8624ca76\n   gem 'benchmark-ips', require: false, group: :development\n+  gem 'rack-mini-profiler', require: false\n+  gem 'flamegraph'\n end\n\n group :test do\ndiff --git a/test/benchmark/app.rb b/test/benchmark/app.rb\nindex ae110ec..ffbc8cc 100644\n--- a/test/benchmark/app.rb\n+++ b/test/benchmark/app.rb\n@@ -54,6 +54,14 @@ end\n\n require 'active_model_serializers'\n\n+begin\n+    require 'rack-mini-profiler'\n+rescue LoadError # rubocop:disable Lint/HandleExceptions\n+else\n+  require 'flamegraph'\n+  # just append ?pp=flamegraph\n+end\n+\n # Initialize app before any serializers are defined, for running across revisions.\n # ref: https://github.com/rails-api/active_model_serializers/pull/1478\n Rails.application.initialize!\n```\n"},"comment":{"url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/comments/291287495","html_url":"https://github.com/rails-api/active_model_serializers/issues/1586#issuecomment-291287495","issue_url":"https://api.github.com/repos/rails-api/active_model_serializers/issues/1586","id":291287495,"user":{"login":"bf4","id":142914,"avatar_url":"https://avatars1.githubusercontent.com/u/142914?v=3","gravatar_id":"","url":"https://api.github.com/users/bf4","html_url":"https://github.com/bf4","followers_url":"https://api.github.com/users/bf4/followers","following_url":"https://api.github.com/users/bf4/following{/other_user}","gists_url":"https://api.github.com/users/bf4/gists{/gist_id}","starred_url":"https://api.github.com/users/bf4/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bf4/subscriptions","organizations_url":"https://api.github.com/users/bf4/orgs","repos_url":"https://api.github.com/users/bf4/repos","events_url":"https://api.github.com/users/bf4/events{/privacy}","received_events_url":"https://api.github.com/users/bf4/received_events","type":"User","site_admin":false},"created_at":"2017-04-03T22:03:23Z","updated_at":"2017-04-03T22:03:23Z","body":"@metaskills Thanks so much for this! Added an issue there https://github.com/customink/amstest/issues/1"}}
{"actor":{"display_login":"bf4"}}