Caching doesn't improve performance #1586
Comments
|
Apparently @joaomdmoura had already discussed this in #1020. I missed this since the issue title was 'Understanding caching', but the contents were that caching made things worse. So, this has been a known issue since July 2015. Sigh. |
|
On interpreting Flamegraphs http://community.miniprofiler.com/t/how-to-deal-with-information-overload-in-flamegraphs/437?u=sam |
|
Note: this benchmark is faulty since some legacy AMS idiosyncrasy made it so that the cached serializer actually did twice the work. Could you re-run @bf4? |
|
Sure. Related to my reference to #1478 above, I'd like to remove per-serializer cache_store configuration. I just don't see the benefit for the complexity it adds. |
|
For updated benchmarks, see #1698 |
|
@bf4 I picked this issue since it might be related to performance boosts. Are there any plans to come up with something along the lines of ActiveRecord's preload for serializers? I see a lot of has_one relations that could be streamlined in a single call not using multi fetches. I also see some Collection serializations not using it as well in my tests (0.10.0 release, not master). |
|
@zaaroth there's improvements in master which I just released in |
|
Is there any update on this issue ? Does caching improve performance now ? |
|
@bf4 Is this still an issue? It's still listed as a warning in the caching guide in master, but I can't seem to find any updates. |
|
It's much better thqn when I first made the issue, but I'm not yet satisfied to close it until I have some benchmarks
B mobile phone
… On Jan 4, 2017, at 2:34 PM, Stephen Dolan ***@***.***> wrote:
@bf4 Is this still an issue? It's still listed as a warning in the caching guide in master, but I can't seem to find any updates.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.
|
|
Wondering if this is till an issue, can't find to much information around this. |
|
@mustela Basically, I haven't yet found an app I can test performance against in a way that make me comfortable changing the language. The perf is much improved since I made the issue, but between life and lacking a good test example, I just haven't followed up. |
|
@bf4 would you mind to describe the app you are looking for? Maybe we can help with that. |
|
@mustela Probably the simplest thing to extract would be a setup with
|
|
I created a simple app to exercise the issue I was facing. |
|
@metaskills Thanks so much for this! Added an issue there customink/amstest#1 |
|
I can say that in my case caching worked like a charm. It saved me about 93% of serialization time. Using AMS 0.10.5. I'm serializing a lot of data though. Before Caching: After Caching: (Images are from Skylight.io) |
|
@mrsweaters Fantastic! are you able to describe in general terms the nature of what you're serializing such that I can model it? like db tables, fields, indices, associations, number of items, how you've configured your serializers, etc? |
|
@bf4 I had to temporarily disable caching unfortunately because Carrierwave can't be serialized. Once I find a workaround I'll try to summarize my situation. |
|
@mrsweaters Do you have overridden attributes that are costly to compute? |
|
@bf4 - I see how caching improves situations in testapp provided by metaskills where the controller is busy doing some computation. However, in my case - where I try to serialize 10,000 records or so, it is still faster to regenerate json than fetch from memcached or redis. The sample app I used for this test was pretty straightforward with a model having 5 attributes, no relationships. Is this expected? |
I saw this too. Basically it was due to excessive children caching and and poor support for russian doll strategies and/or read multi. We solved that first by caching at the top layer only, then moving to JBuilder and a solution with read multi support. |
|
I do see "[active_model_serializers] Cache read_multi: [" ...entries from dalli memcached ..."] in my output, so I'm assuming this means that its performing multi_read. Perhaps, the outstanding issue is something like Russian Doll strategy for caching where AMS would cache both individual entries and the entire response. |
|
Hey everyone, I'm trying to understand how cache works for AMS since I'm not sure if this is a bug or how it works but I've made a simple Rails API with a basic configuration: https://github.com/mustela/ams-cache. The schema is simple: User => Memberships => Organizations Cache enabled, Serializers and the controller which is returning the user + the organizations. So basically when I request This is the response that I get every time I call that endpoint. I understand that user is being read to create the cache key, but the organizations are not being cached. Postgres transaction log, for every request: In redis the keys are being saved: Also the cache prefix key I set here, is not being used at all. As you can see the redis keys doesn't include that prefix. So wondering if anyone could explain what should be cached and what not. Thanks! |
|
@mustela I think the reason caching isnt working on the User model is because its dependencies are not cached. If I'm right, you would need to add cache to serializers for memberships and organizations as well. |
|
@harbirg they have, unless there is another way to specify that. All the serializers inherit from https://github.com/mustela/ams-cache/blob/master/app/serializers/abstract_serializer.rb#L2 |
|
@bf4 the app I published has (I think) all the things you are mentioning. If you are familiar with docker, you should run the app easily. Thanks |
|
@mustela - I forked your repro here https://github.com/harbirg/ams-cache If you review the responses with both caching enabled or not, DB is accessed for both User and Organization models first. For Caching, It likely to check if the cache is dirty or not. If it is not, then readback memcached version. For non-caching case, it starts to regenerate the JSON response after DB access. |
|
Thanks @harbirg, your tests are correct, that's what I'm seeing and as you can see, using caching is way much slower than not using it. I'm trying to put more tests/benchmarks in place to help here. |
|
I just noticed something that seems fishy here. I have a resource and am using the
I found however that I would still get cache misses, because AMS is actually trying to read from:
all the time. This is happening because the def serializable_hash(options = nil)
options = serialization_options(options)
serialized_hash = { root => Attributes.new(serializer, instance_options).serializable_hash(options) }
serialized_hash[meta_key] = meta unless meta.blank?
self.class.transform_key_casing!(serialized_hash, instance_options)
end
# attributes:7
serialized_hash = serializer.serializable_hash(instance_options, options, self)
#serializer:356
def serializable_hash(adapter_options = nil, options = {}, adapter_instance = self.class.serialization_adapter_instance)
adapter_options ||= {}
options[:include_directive] ||= ActiveModel::Serializer.include_directive_from_options(adapter_options)
resource = attributes_hash(adapter_options, options, adapter_instance)
relationships = associations_hash(adapter_options, options, adapter_instance)
resource.merge(relationships)
end
#serializer: 385
def attributes_hash(_adapter_options, options, adapter_instance)
if self.class.cache_enabled?
fetch_attributes(options[:fields], options[:cached_attributes] || {}, adapter_instance)
elsif self.class.fragment_cache_enabled?
fetch_attributes_fragment(adapter_instance, options[:cached_attributes] || {})
else
attributes(options[:fields], true)
end
end
#caching:220
def fetch_attributes(fields, cached_attributes, adapter_instance)
key = cache_key(adapter_instance)
cached_attributes.fetch(key) do
fetch(adapter_instance, serializer_class._cache_options, key) do
attributes(fields, true)
end
end
endAll this means, as far as I can tell, that the cache is always reading from the |
|
Looks like I can ameliorate the above issue one of:
|
|
@ledhed2222 Great catch! Do you think you could write a failing test for it? This was probably introduced later (by me). Json's implementation of serializable_hash is: def serializable_hash(options = nil)
options = serialization_options(options)
- serialized_hash = { root => Attributes.new(serializer, instance_options).serializable_hash(options) }
+ serialized_hash = { root => super(options) }should be sufficient. really, the two adapters should be unified again imho. |
|
Yeah I can work on that at some point @bf4 - thinking about this further, that issue definitely doesn't have anything to do with cache performance (obviously actually). I will say that I've personally encountered this now. I replaced an existing route that did not use AMS and that had cache hit rates of ~0.66 and whose average request time was 250 ms with AMS. My AMS implementation has as cache hit rate of ~0.86 but the average request time actually degraded to about 450 ms. I decided to continue using AMS for serialization, but to hit the cache myself much more directly: serializers = user.resources.reduce({}) do |memo, resource|
s = ActiveModelSerializers::SerializableResource.new(resource, options: options)
memo[s.object_cache_key] = s
memo
end
results = Rails.cache.fetch_multi(*serializers.keys) do |missing_key|
serializers[missing_key].as_json
end.values
render json: resultsBy actually skipping AMS for the cache-lookup and render steps I got my average response time down to 190 ms. So - anecdotally - this looks like an issue of AMS doing too much just to compute cache keys and read them. As indicated by the first poster. |
|
So, as I understand the problem underlies here: That cause cache computing to be more exhaustive that don't use cache at all, right? I guess it's because AMS attempts to do a cache based on the attributes set? Questions:
on the environment's configuration file or in an initializer, that should even overwrite the Wouldn't be a good idea to add this to Readme.MD while this issue got fixed?
@mrsweaters Are you sure the After cache is faster? why it has more allocations? the more allocations it has is not the better? I wonder if first result is 1569ms or 1.5ms |
Expected behavior vs actual behavior
Expected: Configure a cache and using the AMS serializer cache method should improve rendering performance.
Actual: performance decreases AND more objects are allocated.
Steps to reproduce
current master:
git co fa0bc95.Number vary somewhat over runs but differences are consistent.
Environment
0.10.0.rc4, on reffa0bc95ruby -e "puts RUBY_DESCRIPTION"ruby 2.2.3p173 (2015-08-18 revision 51636) [x86_64-darwin14]OS Type & Version:
uname -aDarwin 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.15Integrated application and version
bundle show activemodel.bundle/ruby/2.2.0/gems/activemodel-4.0.13Backtrace
N/A
Additional helpful information
Cache developments since then:
However:
{ "commit_hash": "43312fa^", "version": "0.10.0.rc3", "benchmark_run[environment]": "2.2.2p95", "runs": [ { "benchmark_type[category]": "caching on: caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 687.045, "benchmark_run[result][total_allocated_objects_per_iteration]": 1426 }, { "benchmark_type[category]": "caching off: caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 688.588, "benchmark_run[result][total_allocated_objects_per_iteration]": 1426 }, { "benchmark_type[category]": "caching on: non-caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 849.889, "benchmark_run[result][total_allocated_objects_per_iteration]": 1084 }, { "benchmark_type[category]": "caching off: non-caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 769.596, "benchmark_run[result][total_allocated_objects_per_iteration]": 1084 } ] }{ "commit_hash": "43312fa", "version": "0.10.0.rc3", "benchmark_run[environment]": "2.2.2p95", "runs": [ { "benchmark_type[category]": "caching on: caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 635.297, "benchmark_run[result][total_allocated_objects_per_iteration]": 1519 }, { "benchmark_type[category]": "caching off: caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 601.3, "benchmark_run[result][total_allocated_objects_per_iteration]": 1519 }, { "benchmark_type[category]": "caching on: non-caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 782.07, "benchmark_run[result][total_allocated_objects_per_iteration]": 1113 }, { "benchmark_type[category]": "caching off: non-caching serializers: gc off", "benchmark_run[result][iterations_per_second]": 771.094, "benchmark_run[result][total_allocated_objects_per_iteration]": 1113 } ] }So maybe we should take a look at usage in bulk_cache_fetcher
And with more objects it gets worse:
Possibly related
Flamegraph
bin/serve_benchmark startand the flamegraph gemThe text was updated successfully, but these errors were encountered: