MySQL transaction deadlocks with multiple simultaneous recurring contribution updates

When Authorize.net (not sure about other payment processors) sends more than a few (our current case is 11) silent updates back to CiviCRM in quick succession when a recurring payment has been processed, consistently at least two of them don't get recorded in CiviCRM due to a MySQL transaction deadlock. It isn't always the same two recurring subscriptions.

---------------------------

Relevant CiviCRM log output:

Sep 17 04:50:22 [info] Contribution record updated successfully

Sep 17 04:50:22 [info] Success: Database updated

Sep 17 04:52:40 [info] Subscription payment failed - 'The credit card has expired.'

Sep 17 04:52:40 [info] Contribution record updated successfully

Sep 17 04:52:40 [info] Success: Database updated

Sep 17 04:52:40 [info] Contribution record updated successfully

Sep 17 04:52:40 [info] Success: Database updated

Sep 17 04:52:41 [info] Contribution record updated successfully

Sep 17 04:52:41 [info] Success: Database updated

Sep 17 04:52:41 [info] $Fatal Error Details = Array
(
[callback] => Array
(
[0] => CRM_Core_Error
[1] => handle
)

[code] => -1
[message] => DB Error: unknown error
[mode] => 16
[debug_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1144 , 8948 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[type] => DB_Error
[user_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1144 , 8948 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::handle prefix="" info="INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1144 , 8948 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)

Sep 17 04:52:41 [info] $backTrace = #0 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Error.php(197): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 [internal function](): CRM_Core_Error::handle(Object(DB_Error))
#2 /var/www/example.org/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error))
#3 /var/www/example.org/sites/all/modules/civicrm/packages/DB.php(969): PEAR_Error->PEAR_Error("DB Error: unknown error", -1, 16, (Array:2), "INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#4 /var/www/example.org/sites/all/modules/civicrm/packages/PEAR.php(564): DB_Error->DB_Error(-1, 16, (Array:2), "INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#5 /var/www/example.org/sites/all/modules/civicrm/packages/DB/common.php(1905): PEAR->raiseError(NULL, -1, NULL, NULL, "INSERT INTO civicrm_activity_contact (activity_id, contact_id , record_type_...", "DB_Error", TRUE)
#6 /var/www/example.org/sites/all/modules/civicrm/packages/DB/mysql.php(898): DB_common->raiseError(-1, NULL, NULL, NULL, "1213 ** Deadlock found when trying to get lock; try restarting transaction")
#7 /var/www/example.org/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError()
#8 /var/www/example.org/sites/all/modules/civicrm/packages/DB/common.php(1216): DB_mysql->simpleQuery("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#9 /var/www/example.org/sites/all/modules/civicrm/packages/DB/DataObject.php(2421): DB_common->query("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#10 /var/www/example.org/sites/all/modules/civicrm/packages/DB/DataObject.php(1055): DB_DataObject->query("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type...")
#11 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/DAO.php(278): DB_DataObject->insert()
#12 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/ActivityContact.php(63): CRM_Core_DAO->save()
#13 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(364): CRM_Activity_BAO_ActivityContact::create((Array:3))
#14 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1859): CRM_Activity_BAO_Activity::create((Array:10))
#15 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/BaseIPN.php(586): CRM_Activity_BAO_Activity::addActivity(Object(CRM_Contribute_BAO_Contribution), NULL, NULL)
#16 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/AuthorizeNetIPN.php(183): CRM_Core_Payment_BaseIPN->completeTransaction((Array:28), (Array:6), (Array:8), Object(CRM_Core_Transaction), Object(CRM_Contribute_BAO_ContributionRecur))
#17 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/AuthorizeNetIPN.php(72): CRM_Core_Payment_AuthorizeNetIPN->recur((Array:28), (Array:6), (Array:8), FALSE)
#18 /var/www/example.org/sites/all/modules/civicrm/extern/authorizeIPN.php(40): CRM_Core_Payment_AuthorizeNetIPN->main()
#19

{main}

Sep 17 04:52:41 [info] $Fatal Error Details = Array
(
[callback] => Array
(
[0] => CRM_Core_Error
[1] => handle
)

[code] => -1
[message] => DB Error: unknown error
[mode] => 16
[debug_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1145 , 8954 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[type] => DB_Error
[user_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1145 , 8954 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]
[to_string] => [db_error: message="DB Error: unknown error" code=-1 mode=callback callback=CRM_Core_Error::handle prefix="" info="INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1145 , 8954 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)

Sep 17 04:52:41 [info] $backTrace = #0 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Error.php(197): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 [internal function](): CRM_Core_Error::handle(Object(DB_Error))
#2 /var/www/example.org/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error))
#3 /var/www/example.org/sites/all/modules/civicrm/packages/DB.php(969): PEAR_Error->PEAR_Error("DB Error: unknown error", -1, 16, (Array:2), "INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#4 /var/www/example.org/sites/all/modules/civicrm/packages/PEAR.php(564): DB_Error->DB_Error(-1, 16, (Array:2), "INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#5 /var/www/example.org/sites/all/modules/civicrm/packages/DB/common.php(1905): PEAR->raiseError(NULL, -1, NULL, NULL, "INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...", "DB_Error", TRUE)
#6 /var/www/example.org/sites/all/modules/civicrm/packages/DB/mysql.php(898): DB_common->raiseError(-1, NULL, NULL, NULL, "1213 ** Deadlock found when trying to get lock; try restarting transaction")
#7 /var/www/example.org/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError()
#8 /var/www/example.org/sites/all/modules/civicrm/packages/DB/common.php(1216): DB_mysql->simpleQuery("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#9 /var/www/example.org/sites/all/modules/civicrm/packages/DB/DataObject.php(2421): DB_common->query("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_...")
#10 /var/www/example.org/sites/all/modules/civicrm/packages/DB/DataObject.php(1055): DB_DataObject->query("INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type...")
#11 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/DAO.php(278): DB_DataObject->insert()
#12 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/ActivityContact.php(63): CRM_Core_DAO->save()
#13 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(364): CRM_Activity_BAO_ActivityContact::create((Array:3))
#14 /var/www/example.org/sites/all/modules/civicrm/CRM/Activity/BAO/Activity.php(1859): CRM_Activity_BAO_Activity::create((Array:10))
#15 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/BaseIPN.php(586): CRM_Activity_BAO_Activity::addActivity(Object(CRM_Contribute_BAO_Contribution), NULL, NULL)
#16 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/AuthorizeNetIPN.php(183): CRM_Core_Payment_BaseIPN->completeTransaction((Array:28), (Array:6), (Array:8), Object(CRM_Core_Transaction), Object(CRM_Contribute_BAO_ContributionRecur))
#17 /var/www/example.org/sites/all/modules/civicrm/CRM/Core/Payment/AuthorizeNetIPN.php(72): CRM_Core_Payment_AuthorizeNetIPN->recur((Array:28), (Array:6), (Array:8), FALSE)
#18 /var/www/example.org/sites/all/modules/civicrm/extern/authorizeIPN.php(40): CRM_Core_Payment_AuthorizeNetIPN->main()
#19 {main}

Sep 17 04:52:41 [info] Contribution record updated successfully

Sep 17 04:52:41 [info] Success: Database updated

Sep 17 04:52:41 [info] Contribution record updated successfully

Sep 17 04:52:41 [info] Success: Database updated

Sep 17 04:55:11 [info] Subscription payment failed - 'The credit card has expired.'

Sep 17 05:00:46 [info] Contribution record updated successfully

Sep 17 05:00:46 [info] Success: Database updated

Sep 17 05:03:25 [info] Contribution record updated successfully

Sep 17 05:03:25 [info] Success: Database updated

Sep 17 05:07:11 [info] Contribution record updated successfully

Sep 17 05:07:11 [info] Success: Database updated

---------------------------

Relevant MySQL deadlock output:

Sep 17 04:52:41 mysqld: InnoDB: transactions deadlock detected, dumping detailed information.
Sep 17 04:52:41 mysqld: 140917 4:52:41
Sep 17 04:52:41 mysqld: *** (1) TRANSACTION:
Sep 17 04:52:41 mysqld: TRANSACTION 8408262, ACTIVE 0 sec inserting
Sep 17 04:52:41 mysqld: mysql tables in use 1, locked 1
Sep 17 04:52:41 mysqld: LOCK WAIT 30 lock struct(s), heap size 2496, 15 row lock(s), undo log entries 10
Sep 17 04:52:41 mysqld: MySQL thread id 65844, OS thread handle 0xa6bceb70, query id 9658748 localhost lm update
Sep 17 04:52:41 mysqld: INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1143 , 8946 , 2 )
Sep 17 04:52:41 mysqld: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408262 lock_mode X insert intention waiting
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** (2) TRANSACTION:
Sep 17 04:52:41 mysqld: TRANSACTION 8408264, ACTIVE 0 sec inserting
Sep 17 04:52:41 mysqld: mysql tables in use 1, locked 1
Sep 17 04:52:41 mysqld: 30 lock struct(s), heap size 2496, 15 row lock(s), undo log entries 10
Sep 17 04:52:41 mysqld: MySQL thread id 65845, OS thread handle 0xa478bb70, query id 9658755 localhost lm update
Sep 17 04:52:41 mysqld: INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1144 , 8948 , 2 )
Sep 17 04:52:41 mysqld: *** (2) HOLDS THE LOCK(S):
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408264 lock_mode X
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408264 lock_mode X insert intention waiting
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** WE ROLL BACK TRANSACTION (2)
Sep 17 04:52:41 mysqld: InnoDB: transactions deadlock detected, dumping detailed information.
Sep 17 04:52:41 mysqld: 140917 4:52:41
Sep 17 04:52:41 mysqld: *** (1) TRANSACTION:
Sep 17 04:52:41 mysqld: TRANSACTION 8408263, ACTIVE 0 sec inserting
Sep 17 04:52:41 mysqld: mysql tables in use 1, locked 1
Sep 17 04:52:41 mysqld: LOCK WAIT 30 lock struct(s), heap size 2496, 15 row lock(s), undo log entries 10
Sep 17 04:52:41 mysqld: MySQL thread id 65846, OS thread handle 0xa456cb70, query id 9658773 localhost lm update
Sep 17 04:52:41 mysqld: INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1145 , 8954 , 2 )
Sep 17 04:52:41 mysqld: *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408263 lock_mode X insert intention waiting
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** (2) TRANSACTION:
Sep 17 04:52:41 mysqld: TRANSACTION 8408262, ACTIVE 0 sec inserting
Sep 17 04:52:41 mysqld: mysql tables in use 1, locked 1
Sep 17 04:52:41 mysqld: 31 lock struct(s), heap size 2496, 16 row lock(s), undo log entries 10
Sep 17 04:52:41 mysqld: MySQL thread id 65844, OS thread handle 0xa6bceb70, query id 9658748 localhost lm update
Sep 17 04:52:41 mysqld: INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 1143 , 8946 , 2 )
Sep 17 04:52:41 mysqld: *** (2) HOLDS THE LOCK(S):
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408262 lock_mode X
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
Sep 17 04:52:41 mysqld: RECORD LOCKS space id 0 page no 32836 n bits 864 index `FK_civicrm_activity_contact_activity_id` of table `lm_civi`.`civicrm_activity_contact` trx id 8408262 lock_mode X insert intention waiting
Sep 17 04:52:41 mysqld: Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
Sep 17 04:52:41 mysqld: 0: len 8; hex 73757072656d756d; asc supremum;;
Sep 17 04:52:41 mysqld:
Sep 17 04:52:41 mysqld: *** WE ROLL BACK TRANSACTION (1)

---------------------------

The curious part about this is that it's deadlocking on a foreign key constraint when trying to create the contacts of the activity for the contribution, not than the contribution itself, which I would assume procedurally has already created. I've looked through the code a bit and I'm pretty sure this is the relevant section, CRM/Core/Payment/BaseIPN.php, line 578 in 4.4.7 branch.

// create an activity record
if ($input['component'] == 'contribute') {
//CRM-4027
$targetContactID = NULL;
if (!empty($ids['related_contact']))

{ $targetContactID = $contribution->contact_id; $contribution->contact_id = $ids['related_contact']; }

CRM_Activity_BAO_Activity::addActivity($contribution, NULL, $targetContactID);
// event
}
else

{ CRM_Activity_BAO_Activity::addActivity($participant); }

CRM_Core_Error::debug_log_message("Contribution record updated successfully");

But we're not sure how to fix the problem. It doesn't seem like a MySQL server configuration fix (as far as I've read). We're (Palante) willing to fix this problem but wanted to get some guidance on the best approach to take.