Fix array-cache-bypass - in FastArrays on has()

[eileenmcnaughton]

Overview

Fix array-cache-bypass in FastArrays on has()

When running the tokenProcessor (notably in processGreetings when creating a contact) it uses the metadata cache. This cache stores .. erm ... metadata using the preferred cache method for the site aided by an in-process cache on the CRM_Utils_Cache_FastArrayDecorator class. If the cache key has already been hit in the current php process it is loaded from this php array cache, otherwise it falls back the the preferred cache method (in our case Redis).

However, when the method has is being called it was by-passing the php array cache and going straight to Redis - which was causing a significant performance hit for us.

Before

Calling Civi::cache('metadata')->get() accesses the array cache & only falls back to (eg.) Redis if no key exists. However, Civi::cache('metadata')->has() always by-passed the array cache & hits (eg) Redis

After

Calling Civi::cache('metadata')->has() also accesses the array cache, where possible.

Technical Details

This appears to just be a coding over-sight as the CRM_Utils_Cache_ArrayDecorator class was not impacted.

Comments

I feel like the performance hit I was seeing on our staging server sing Redis was surprisingly high (higher than using the sqlCache would have been) so I think there is also an investigation at our end to see if it was higher than it should be

[civibot]

(Standard links)

• If this is your first pull-request for CiviCRM, please browse CONTRIBUTING.md for information about the development and testing processes.
• If you are reviewing this pull-request, you may wish to consult the test sites and the Review Standards (long template, short template).

[seamuslee001]

@johntwyman @andrew-cormick-dockery you might be interested in this given you also use redis

[eileenmcnaughton]

@johntwyman @andrew-cormick-dockery I am VERY interested in your experience - the impact of this change on our staging server was to double our throughput whereas removing 60% of the sql queries in my work last year didn't move the needle. I'm going to open an internal ticket to see if our Redis is slower than our other components for some reason but would love to hear if this helps you

[johntwyman]

@eileenmcnaughton we've had a lot of real problems with mail construction/delivery of late, so I'm definitely keen to try this out. I'll discuss this with @andrew-cormick-dockery today.

In our instance Redis is doing an enormous amount of work but we're not even touching the sides of what the Redis instance could be doing. At the peak of a mailing job, Redis is handling ~80-100 connections, 15k keys and pushing out ~60Mb/s of data. But CPU and RAM utilisation is minimal. So if Redis is a bottleneck I think it's only by virtue of how much Civi is relying on it.

[johntwyman]

@eileenmcnaughton we're using New Relic at the moment and have a growing number of traces that might be of interest too. I'm not sure how easily I can share these traces but if you do want to have a look, let me know. I'm sure we can figure something out.

[eileenmcnaughton]

@johntwyman lets connect next week when you have tested this out & I have some input from our tech-ops team. The big open question for me at the moment is whether the performance improvement I saw with this will be replicated on production or if the staging environment has some additional latency - this is our WMF ticket on the issue https://phabricator.wikimedia.org/T314619

[eileenmcnaughton]

We just deployed this - you can see clearly when in the graph excerpt - the action tracked is basically updating a contact including their greetings

[colemanw]

I've reviewed the code and it looks good. Merging based on review and testing by WMF.

[johntwyman]

We haven't seen as dramatic an improvement in our testing but it's definitely made a difference. Thanks @eileenmcnaughton

[eileenmcnaughton]

@johntwyman two possible reasons

• our redis is different & there is something in there and
• the above chart is very targetted on a particular bit of code with already-warm caches

[johntwyman]

We had a recent mailing with ~280,000 recipients. Prior to this patch it would have sent at ~1,000 emails per minute or worse. With this patch it sent at ~4,000 emails per minute.

That being said, last year a mailing of this size for us would have sent at 8-10,000 emails per minute. The big changes in that time that I can point to are Civi version upgrades and making FlexMailer the default mailing subsystem.

I haven't had time to fully dig into what exactly is going on but I know this much:

• Redis calls are through the roof (hence the improvement with this patch)
• The payload of the cache calls seems fairly large
• Legacy token evaluation is one bottleneck

I won't keep flooding this merged PR with comments but over the next few weeks we'll be looking into this in more detail. Specifically we'll be examining New Relic traces to see the tree of function calls and the data that's being stored in Redis. Redis itself doesn't seem bothered (ie. no CPU, RAM, etc., constraints) but it's certainly handling a large volume of calls relating to mailings.

[eileenmcnaughton]

@johntwyman any chance you could test d36378f - we are testing it now - with unclear results but I think something else is in play. In the staging environment I got another small improvement (only maybe ten percent) on this one

[eileenmcnaughton]

Also this follow up #24292

[eileenmcnaughton]

#24294 is #24156 (comment)