Deadlocks on acl_cache

One of the prevalent deadlocks we see is on the acl_contact_cache. I've found that I can replicate this locally fairly consistently just by running 2 sets of tests at once.

The thing that is somewhat odd about this is that we don't use ACLs at all so in fact the table is always empty. Notably the table is also extremely slow to truncate - despite being empty.

What happens The flow we have is

1. api call to create a contact
2. when the contact is created CRM_Contact_BAO_Contact_Utils::clearContactCaches() is called. It hits a deadlock because

• it has an FK to contact.id (& in our case it has an FK and an index seemingly)

• it is called a lot

3. it retries and succeeds
4. we then try to add an email - the add function fails on a foreign key constraint because the earlier deadlock rolled the contact create back

Proposals I think there are a number of things we can do & we should do some combo:

• Make the delete function less expensive & less locky

• a) Add an index on modified date - we are constantly deleting where modified_date < x so let's index it (done 5.22)

• a.1) possibly add a warning for any sites missing the index in a - ie we have a system check but an early return was added

• remove the index on acl_id - we ALSO have an FK so having both is probably harmless-but-confusing

• alter the FK on contact ID to be an index not a foreign key. This is perhaps a confusing suggestion but it is also the one that will make a real dent in these deadlocks. Remember this is a cache table not a 'persistent' table. The impact of the rows outliving the existence of the contact for a little bit is basically none because we don't do ACL lookups on non-existent contacts (this is also potentially helpful for better handling 0 or anonymous contact_id where we've had to work around this before

• Protect against conflict through mysql locks. I think we can use a mysql lock to avoid 2 processes attempting this flush at once. I'll do a PR for this

• How often do we REALLY need to flush those caches. Maybe we could cache a 'last flushed' key & flush no more than every 30 seconds.

• Consider checking if the table is empty before attempting to empty it.

• Review the places where acl cache is called from & decide how necessary there are - here is the list:

CRM_ACL_BAO_Cache::resetCache CRM/Contact/BAO/Contact/Utils.php: CRM_ACL_BAO_Cache::resetCache(); CRM/Core/BAO/Cache.php: CRM_ACL_BAO_Cache::resetCache(); CRM/Utils/System.php: CRM_ACL_BAO_Cache::resetCache(); CRM/ACL/Page/EntityRole.php: CRM_ACL_BAO_Cache::resetCache(); CRM/ACL/Form/ACLBasic.php: CRM_ACL_BAO_Cache::resetCache(); CRM/ACL/Form/EntityRole.php: CRM_ACL_BAO_Cache::resetCache(); CRM/ACL/BAO/ACL.php: CRM_ACL_BAO_Cache::resetCache();

CRM_Contact_BAO_Contact_Utils::clearContactCaches() CRM/Contact/BAO/Contact/Utils.php: public static function clearContactCaches($isEmptyPrevNextTable = FALSE) { CRM/Contact/BAO/GroupContact.php: CRM_Contact_BAO_Contact_Utils::clearContactCaches(); CRM/Contact/BAO/GroupContact.php: CRM_Contact_BAO_Contact_Utils::clearContactCaches(); CRM/Contact/BAO/Contact.php: CRM_Contact_BAO_Contact_Utils::clearContactCaches(); CRM/Contact/Import/Form/Preview.php: CRM_Contact_BAO_Contact_Utils::clearContactCaches(TRUE); bin/cli.class.php: CRM_Contact_BAO_Contact_Utils::clearContactCaches();

[ ] A bigger task perhaps - but permit opportunistic flushing to be turned off in favour of a cron (per group contact cache)

Deadlock output

LATEST DETECTED DEADLOCK

2019-12-19 11:29:45 0x700010cd2000 *** (1) TRANSACTION: TRANSACTION 34518715, ACTIVE 1 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 11 lock struct(s), heap size 1136, 4 row lock(s), undo log entries 7 MySQL thread id 571, OS thread handle 123145583353856, query id 709677 localhost 127.0.0.1 drupalcivi_lkznr updating DELETE FROM civicrm_acl_cache WHERE modified_date IS NULL OR (modified_date <= '20191218222444') *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 143182 page no 3 n bits 80 index PRIMARY of table drupalcivi_lkznr.civicrm_acl_cache trx id 34518715 lock_mode X waiting Record lock, heap no 2 PHYSICAL RECORD: n_fields 6; compact format; info bits 32 0: len 4; hex 00003c14; asc < ;; 1: len 6; hex 0000020eb6ba; asc ;; 2: len 7; hex 3b000001442ac5; asc ; D* ;; 3: SQL NULL; 4: len 4; hex 00000002; asc ;; 5: SQL NULL;

*** (2) TRANSACTION: TRANSACTION 34518714, ACTIVE 1 sec starting index read mysql tables in use 2, locked 2 66 lock struct(s), heap size 8400, 71 row lock(s), undo log entries 74 MySQL thread id 573, OS thread handle 123145584189440, query id 710022 localhost 127.0.0.1 drupalcivi_lkznr updating UPDATE civicrm_contact SET contact_type = 'Organization' , contact_sub_type = NULL , email_greeting_id = NULL , postal_greeting_id = NULL , addressee_id = 3 , employer_id = 15055 WHERE ( civicrm_contact.id = 15055 ) *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 143182 page no 3 n bits 80 index PRIMARY of table drupalcivi_lkznr.civicrm_acl_cache trx id 34518714 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;;

changed the description

changed title from Deadlocks on acl_contact_cache - I'm still writing this - just hit save & am editing the rest in so I don't lose it to Deadlocks on acl_cache - I'm still writing this - just hit save & am editing the rest in so I don't lose it

added git:civicrm-core sig:bug sig:performance triaged labels

changed title from Deadlocks on acl_cache - I'm still writing this - just hit save & am editing the rest in so I don't lose it to Deadlocks on acl_cache

mentioned in issue #748 (closed)

mentioned in commit 1ca18cc4

mentioned in commit d551d3d6

mentioned in commit 49f5c017

mentioned in issue #2477 (closed)

mentioned in issue #2931 (closed)

As we are non-acl users we no longer see these as we were able to leverage the setting to turn off acl_cache clearing

We have recently been forced to migrate server at short notice (2 x upstream host went into administration) which has caused a number of new issues - not helpful as these are on top of other things I'm currently trying to chase down e.g. tokens - but one thing we are now seeing is loads of deadlocks on acl_contact_cache, which we didn't get before the move.

Here is a recent example:

Aug 15 04:00:11  [error] $Fatal Error Details = Array
(
    [callback] => Array
        (
            [0] => CRM_Core_Error
            [1] => exceptionHandler
        )

    [code] => -31
    [message] => DB Error: deadlock
    [mode] => 16
    [debug_info] => TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
    [type] => DB_Error
    [user_info] => TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
    [to_string] => [db_error: message="DB Error: deadlock" code=-31 mode=callback callback=CRM_Core_Error::exceptionHandler prefix="" info="TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)


Aug 15 04:00:11  [debug] $backTrace = #0 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/Core/Error.php(954): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(922): CRM_Core_Error::exceptionHandler(Object(DB_Error))
#2 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/db/DB.php(997): PEAR_Error->__construct("DB Error: deadlock", -31, 16, (Array:2), "TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found w...")
#3 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(575): DB_Error->__construct(-31, 16, (Array:2), "TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found w...")
#4 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/pear-core-minimal/src/PEAR.php(223): PEAR->_raiseError(Object(DB_mysqli), NULL, -31, 16, (Array:2), "TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found w...", "DB_Error", TRUE)
#5 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/db/DB/common.php(1928): PEAR->__call("raiseError", (Array:7))
#6 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/db/DB/mysqli.php(936): DB_common->raiseError(-31, NULL, NULL, "TRUNCATE TABLE civicrm_acl_contact_cache [nativecode=1213 ** Deadlock found w...", "1213 ** Deadlock found when trying to get lock; try restarting transaction")
#7 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/db/DB/mysqli.php(406): DB_mysqli->mysqliRaiseError()
#8 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/vendor/pear/db/DB/common.php(1234): DB_mysqli->simpleQuery("TRUNCATE TABLE civicrm_acl_contact_cache")
#9 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/packages/DB/DataObject.php(2696): DB_common->query("TRUNCATE TABLE civicrm_acl_contact_cache")
#10 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/packages/DB/DataObject.php(1829): DB_DataObject->_query("TRUNCATE TABLE civicrm_acl_contact_cache")
#11 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/Core/DAO.php(472): DB_DataObject->query("TRUNCATE TABLE civicrm_acl_contact_cache")
#12 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/Core/DAO.php(1709): CRM_Core_DAO->query("TRUNCATE TABLE civicrm_acl_contact_cache", TRUE)
#13 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/ACL/BAO/Cache.php(181): CRM_Core_DAO::singleValueQuery("TRUNCATE TABLE civicrm_acl_contact_cache")
#14 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/ACL/BAO/Cache.php(156): CRM_ACL_BAO_Cache::flushACLContactCache()
#15 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/ACL/BAO/Cache.php(129): CRM_ACL_BAO_Cache::resetCache()
#16 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/CRM/Contact/BAO/Contact/Utils.php(894): CRM_ACL_BAO_Cache::opportunisticCacheFlush()
#17 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/bin/cli.class.php(125): CRM_Contact_BAO_Contact_Utils::clearContactCaches()
#18 /home/cses_org_uk/public_html/administrator/components/com_civicrm/civicrm/bin/cli.php(32): civicrm_cli->callApi()
#19 {main}

It's a virtual server so theoretically all the settings (PHP, MySQL etc) are the same as before, but you never know!

Sounds like there is work in progress to root this out, but just raising this in case helpful and/or there is something we should be doing on our site to prevent this.

We don't use ACLs; the table is always empty.

It sounds like (1) create-contact and (2) clear-caches are performed in the same transaction. Could we run clear-caches in POST_COMMIT (ie, as a separate transaction)?

It would mean that:

• You have two smaller transactions (each touching fewer resources, for less time) rather than one big transaction.
• The update-acl-cache transaction would be more consistent/predictable. (Two concurrent workers that try to update the ACL cache will do locks+queries in the same order. Deadlocks arise when workers access resources in different order.)

(Note: Related comment in #1481 (comment 80480))

We have been having troubles with this on a client site and it is quite troublesome. We were thinking of trying to hack core with something to stop the acl queries as we don't need them. We would like to make this a setting or hook.

assigned to @seamuslee

One more proposal - do we really need to empty the entire civicrm_acl_contact_cache on any contact edit? Could we just recalculate for the edited contact?

I'm aware of acl_cache_refresh_mode but when does editing a contact justify rebuilding the entire cache? Here's all I can think of:

• ACL is based on a smart group - e.g. "spouses of donors" ACL might need to change if you edit a different contact. But it would also need to change if we edited the relationship or contribution, which we don't do.
• A custom aclWhereClause hook in an extension.

I can think of several solutions for each of these. Am I missing anything?

This would solve not only the deadlock issue, but also much of the performance issue of using ACLs.

Hi,

Thank you for raising an issue to help improve CiviCRM. As you may know, this issue has not had any activity for quite some time, so we have closed it.

We would like you to help us to determine if this issue should be re-opened:

• If this issue was reporting a bug, can you attempt to reproduce it on a latest version of CiviCRM?
• If this issue was proposing a new feature, can you verify if the feature proposal is still relevant? Did it get the concept-approved label? Have other people also shown interest? Could it be implemented as an extension?

If the answer to either question is yes, please feel free to comment or re-open the issue. Please also consider:

• Is it something that you could help implement, either by sending a patch or hiring someone who can?
• Would you be willing to fund the work, either through a CiviCRM partner, or the Core Team?

Thank you for your help and contributions to CiviCRM.

P.S. This is an automated message, see infra/gitlab issue 20. We understand that automatic responses are annoying, but given the number of open issues as the project evolves, we need a bit of help to triage and prioritise the most relevant issues.

closed

reopened

As previously discussed, I can make funding available for overhauling how and when the ACL contact cache is emptied.

@josh please consider the generous funding offer.

We can chip in a few hours here too

And JMA too!

Just flagging that CT has a couple of largish chunks of paid work over the couple of months so it's likely any paid work on this would be early next year

Having said that - I'm wondering what the scope of any work would be - obviously I wrote this up 4 years ago I think we have implemented some things - just going through the items above to see which but that's assuming the above list was on the right track

changed the description

changed the description

Ah - WMF stopped having problems with this after the setting acl_cache_refresh_mode was introduced - which we set to TRUE

We don't actually clear the cache through a background process as we used to hit the deadlocks despite not using ACLS but I assume there is a job to do it & if not there could be - which moves it out of the edit contact process

@eileen My funding is coming from an organization using multi-site (so ACLs) - any time that any record is edited, the ACL cache is invalidated. Rebuilding that cache is non-trivial, so non-administrators have a very slow experience.

Using a background job is not a solution for them because if a new contact is created by an ACLed user, they won't be able to access that contact after creation until the cache is rebuilt.

My recommendation (which I'd discussed with Coleman maybe 10-12 months ago) is that we overhaul the ACL cache invalidation:

• If a contact is edited, we should default to only rebuilding that contact's ACL cache records.
• Because ACL cache records are per-user, we need to have some mechanism of knowing which users have an otherwise valid cache, so we can rebuild for all of them.
• We need a mechanism for ACL hooks to indicate that records other than the edited contact should be recalculated. E.g. I have an ACL hook that indicates that spouses of anyone in a particular smart group are also restricted by ACL.

A new idea I had along these lines is to not recalculate the cache for every user - and instead identify which users have an identical permission set, and calculate it once for everyone with the same level of access.

2 things:

• #4639 is a separate ticket that tracks the suggested changes I posted about yesterday.
• @josh - how can I move this forward? I know CT is busy but getting a quote and a start date would be helpful for locking in the funding

"A new idea I had along these lines is to not recalculate the cache for every user - and instead identify which users have an identical permission set, and calculate it once for everyone with the same level of access." - that is an interesting idea - we would need some sort of hash & if hooks intervene they would need to 'register' their own hash or something

@JoeMurray @JonGold @awestbha apologies for the lack of movement on this. I indicated to Jon G yesterday that I had not received notifications from this thread for some reason. I'll put this on the CT agenda for tomorrow and will follow up with you.