cache key logging can have performance side effects

[gingerlime]

I'm looking at behaviour of rails caching when passing a collection (e.g. AR relation), and even though there's already a problem related to this with rails, if/when this problem is fixed, I anticipate a similar problem with the DD tracer at

dd-trace-rb/lib/ddtrace/contrib/rails/active_support.rb

Line 53 in 2828552

cache_key = Datadog::Utils.truncate(payload.fetch(:key), Ext::QUANTIZE_CACHE_MAX_KEY_SIZE)

I tested it with the rails issue patched, and observed that logging the cache key on this line can have a performance side effect of evaluating the key, causing a potentially heavy DB query.

I know this sounds a bit vague, but as a crude example, if my cache key is Project.all, rails would typically evaluate it into a cache key using an efficient DB query (SELECT COUNT(*) AS "size", MAX("projectsl"."updated_at") AS timestamp FROM "projects"), but then when the same key is logged by the Datadog agent, it would evaluate Project.all and generate a much heavier query (SELECT projects".* from "projects").

I'm not very familiar with the dd-tracer, but just observed this when experimenting with this, so I thought I'd report this. Perhaps there's a way to get the key from rails after it's been "expanded" into a string? or use a helper to log the key in a more efficient form? e.g. ActiveSupport::Cache.expand_cache_key(payload.fetch(:key)) ?

[delner]

Thanks for the heads up @gingerlime. If it's as you describe it does sound somewhat concerning.

Just to clarify, users are presumably calling cache.read(key), at which point we intercept that method call and trace. Would key not already be evaluated before reaching the tracer? i.e. Should they not implement cache.read(ActiveSupport::Cache.expand_cache_key(key)) themselves?

[gingerlime]

@delner thanks for looking into this.

In the scenario I described above, this all happens under the hood by Rails, and users would typically use a higher level abstraction / API. For example cache a collection in the view (and therefore pass the Active Record relation to the cache method, and not the key directly).

The view can look like this roughly

<% cache Project.all do %>
...
<% end %>

And then rails would create a key from Project.all to pass to the caching adapter (e.g. redis). Currently, there's a rails bug or limitation that actually causes a similar problem as far as I can tell. But once this bug is fixed, then Rails would do the "right thing", but if it then passes the raw Project.all up to Datadog, then Datadog might not process it correctly.

From my little experiments, this is going to happen. I was able to fix the rails bug, but then saw the problem surface with the DD tracer.

Hope I explained things clearly, but if there's anything I can clarify, please let me know.

[delner]

Is Rails going to auto-detect that the "key" provided (a.k.a. Project.all) is actually an ActiveRecord association, then auto-generate its own optimal cache key based on that knowledge? Without the user having to manage the key format? Do I have that right?

[gingerlime]

TL;DR yes.

Rails has quite a sophisticated mechanism for generating an efficient key from whatever you provide it. You can pass it strings or simple scalars, arrays/enumerables, objects and Active Record relations (e.g. Project.where(:owner => "x").limit(5)), etc. It would "figure out" the most efficient queries to generate a key with (in the case of AR relations, as I described above, it would try to find the last updated_at for a collection as well as the size and incorporate it into the cache key). For enumerables, it does so recursively. Furthermore, there's now a new way to split the key and version info, so the key "stem" is used to retrieve the cache value, but the cache value would include the version as an extra attribute. This kinda "splits" the version info out of the key, see rails/rails#29092

I think it boils down to fairly simple duck-typing for the most part. i.e. The code that generates the key from an object would try to check if the object responds to cache_key and if so, would call it. If not, it would use some other mechanisms for enumeration and serialization. The Active Record relations (and other classes) respond to cache_key obviously.

Hope I explained it clearly. I'm only recently getting more acquainted with the inner magic of rails caching, so please take whatever I say with a grain of salt.

[delner]

This sounds like a very Rails thing to do. The more complexity the library encapsulates and handles, the more difficult it is to inject instrumentation, particularly if the components/functions aren't built in such a way that there's a clean division between the "resolve object to key" step and the "write key/value to cache" step.

We'll have to take a deeper look at this at some point. If this is a common case and the instrumentation is liable to issues with keys as its written right now, we might have to rewrite part of it (perhaps hook into a different part of the caching feature), depending on how the Rails caching components are built.

Thanks for the heads up on this.

[gingerlime]

Yes, it is very Rails-y :)

I tried to see what other tracers like scoutapp are doing, and didn't find any cache instrumentation (but didn't look too deeply).

I think there are ways around this that you guys should consider, maybe only logging scalar values, or basically avoiding any introspection that has side effects (e.g. enumerating recursively, but then mapping with a to_s on each non-enumerable?), or maybe even using Rails' ActiveSupport::Cache.expand_cache_key(key)? Hope you guys can consider some options. Happy to contribute if I can.

[delner]

Yeah, we might be able to do some nicer things with the cache keys: ideally something as simple as possible but not too simple.

If you feel inclined to tinker with some more flexible/simple/performant implementations, we'd very much welcome that. In the mean time, I'll add this to the backlog, so we can schedule this for work in the future.

[delner]

This change should roll with 0.18.2.