Author Topic: No Deadlock Handling (SMS Tracking Survey Extension) (Read 2719 times)

JohnFF · January 14, 2015, 03:53:18 am

Dear Civiites,

Future First has a "tracking survey" extension, that (when an inbound message is received) sends an outbound SMS message. (We have a somewhat upgraded version of code here https://civicrm.org/blogs/michael-mcandrew/chained-sms).

We've encountered a problem with deadlocking MySQL queries: messages appear to be being sent via clickatell, but activities are not being created.

We are using CiviCRM 4.4.6 with Clickatell Extension 1.0 (not 2.0, which is the latest).

We would appreciate

1) any suggestions on how best to prevent these, as is the nature of a survey we have lots of messages entering the system at once (although our load graphs indicate that the MySQL and nginx spikes - although noticeable - weren't very significant.

2) suggestions on how best to help our poor system recover when such things happen. Storing the full query failed somewhere else to be re-run later?

3) in our post hook, we recently inserted a "sleep(3)" command, in an attempt to prevent the inbound and return messages being created in the same second (this was making it hard to follow the order that messages happened in). Could this cause us problems with lots of messages flooding in at once? Is there a better way to achieve the same effect?

Jan 06 18:37:34 [info] $Fatal Error Details = Array
(
[callback] => Array
(

=> CRM_Core_Error

Code: [Select]

 => -1
    [message] => DB Error: unknown error
    [mode] => 16
    [debug_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 307425 ,  82200 ,  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 ( 307425 ,  82200 ,  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 ( 307425 ,  82200 ,  2 )  [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"]
)


Jan 06 18:37:34  [info] $backTrace = #0 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Error.php(770): CRM_Core_Error::backtrace("backTrace", TRUE)
#1 [internal function](): CRM_Core_Error::exceptionHandler(Object(DB_Error))
#2 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error))
#3 /var/www/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError()
#8 /var/www/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/DAO.php(278): DB_DataObject->insert()
#12 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Activity/BAO/ActivityContact.php(63): CRM_Core_DAO->save()
#13 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/Activity/BAO/Activity.php(375): CRM_Activity_BAO_ActivityContact::create((Array:3))
#14 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/SMS/Provider.php(163): CRM_Activity_BAO_Activity::create((Array:)
#15 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.civicrm.sms.clickatell/org_civicrm_sms_clickatell.php(287): CRM_SMS_Provider->createActivity(" bb2ac9479622e680e45914e1a814150b", "Thanks for letting us know! It'd be really helpful if you would also text us ...", (Array:14), NULL, 1)
#16 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/Activity/BAO/Activity.php(1582): org_civicrm_sms_clickatell->send("07777777777", (Array:14), "Thanks for letting us know! It'd be really helpful if you would also text us ...", NULL, 1)
#17 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/Activity/BAO/Activity.php(1506): CRM_Activity_BAO_Activity::sendSMSMessage("18658", "Thanks for letting us know! It'd be really helpful if you would also text us ...", "", (Array:12), 307421, 1)
#18 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.thirdsectordesign.chainsms/api/v3/Contact/Sms.php(75): CRM_Activity_BAO_Activity::sendSMS((Array:1), (Array:7), (Array:12), (Array:1), 1)
#19 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/api/api.php(88): civicrm_api3_contact_sms((Array:3))
#20 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.thirdsectordesign.chainsms/CRM/Chainsms/Processor.php(70): civicrm_api("Contact", "sms", (Array:3))
#21 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.thirdsectordesign.chainsms/chainsms.php(88): CRM_Chainsms_Processor->inbound((Array:13))
#22 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.thirdsectordesign.chainsms/chainsms.php(131): chainsms_post_respond_to_inbound_sms("create", "Activity", 307413, Object(CRM_Activity_DAO_Activity))
#23 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Utils/Hook.php(160): chainsms_civicrm_post("create", "Activity", 307413, Object(CRM_Activity_DAO_Activity))
#24 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Utils/Hook/Drupal.php(67): CRM_Utils_Hook->runHooks((Array:139), "civicrm_post", 4, "create", "Activity", 307413, Object(CRM_Activity_DAO_Activity), "create")
#25 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Utils/Hook.php(227): CRM_Utils_Hook_Drupal->invoke(4, "create", "Activity", 307413, Object(CRM_Activity_DAO_Activity), "create", "civicrm_post")
#26 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/Activity/BAO/Activity.php(612): CRM_Utils_Hook::post("create", "Activity", 307413, Object(CRM_Activity_DAO_Activity))
#27 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/SMS/Provider.php(250): CRM_Activity_BAO_Activity::create((Array:9))
#28 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.civicrm.sms.clickatell/org_civicrm_sms_clickatell.php(391): CRM_SMS_Provider->processInbound("44777777777", "A", NULL, "5bdf22d6cf2913932968e5fe9388a4b2")
#29 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/SMS/Page/Callback.php(45): org_civicrm_sms_clickatell->inbound()
#30 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(323): CRM_SMS_Page_Callback->run((Array:3), NULL)
#31 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(72): CRM_Core_Invoke::runItem((Array:12))
#32 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke((Array:3))
#33 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke((Array:3))
#34 [internal function](): civicrm_invoke("sms", "callback")
#35 /var/www/html/prod/drupal-7.34/includes/menu.inc(517): call_user_func_array("civicrm_invoke", (Array:2))
#36 /var/www/html/prod/drupal-7.34/index.php(21): menu_execute_active_handler()
#37 {main}

DaveFF · January 14, 2015, 04:43:59 am

The above backtrace shows an outbound SMS (the second survey question) failing to be recorded in response to an inbound SMS (the answer to the first question). We're pretty sure the contact received it- as Clickatell says they did, and they replied to it, but the activity wasn't recorded.

We also have instances of an inbound SMS itself failing to be recorded, also on the INSERT INTO civicrm_activity_contact part. In this case, the failing inbound SMS is a reply to the second question. Also missing (most likely because of the failure to record the inbound) is the outbound that should have been sent thanking the contact for their time.

Quote

Jan 07 17:40:10 [info] $Fatal Error Details = Array
(
[callback] => Array
(

=> CRM_Core_Error
[1] => handle
)

Code: [Select]
=> -1 [message] => DB Error: unknown error [mode] => 16 [debug_info] => INSERT INTO civicrm_activity_contact (activity_id , contact_id , record_type_id ) VALUES ( 314341 , 103134 , 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 ( 314341 , 103134 , 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 ( 314341 , 103134 , 2 ) [nativecode=1213 ** Deadlock found when trying to get lock; try restarting transaction]"] ) Jan 07 17:40:10 [info] $backTrace = #0 /var/www/html/prod/drupal-7.34/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/html/prod/drupal-7.34/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error)) #3 /var/www/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError() #8 /var/www/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/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/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/DAO.php(278): DB_DataObject->insert() #12 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Activity/BAO/ActivityContact.php(63): CRM_Core_DAO->save() #13 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/Activity/BAO/Activity.php(375): CRM_Activity_BAO_ActivityContact::create((Array:3)) #14 /var/www/html/prod/drupal-7.34/sites/default/civicrm_custom_php/CRM/SMS/Provider.php(250): CRM_Activity_BAO_Activity::create((Array:9)) #15 /var/www/html/prod/drupal-7.34/sites/default/extensions/org.civicrm.sms.clickatell/org_civicrm_sms_clickatell.php(391): CRM_SMS_Provider->processInbound("44<redacted mobile number>", "<redacted inbound text>", NULL, "5bdec10ad7d9574ff19fbc8f4b5fb6fa") #16 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/SMS/Page/Callback.php(45): org_civicrm_sms_clickatell->inbound() #17 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(323): CRM_SMS_Page_Callback->run((Array:3), NULL) #18 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(72): CRM_Core_Invoke::runItem((Array:12)) #19 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke((Array:3)) #20 /var/www/html/prod/drupal-7.34/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke((Array:3)) #21 [internal function](): civicrm_invoke("sms", "callback") #22 /var/www/html/prod/drupal-7.34/includes/menu.inc(517): call_user_func_array("civicrm_invoke", (Array:2)) #23 /var/www/html/prod/drupal-7.34/index.php(21): menu_execute_active_handler() #24 {main} [/quote]

totten · January 14, 2015, 05:12:27 pm

Deadlocks can be difficult to fix.

A few random replies/thoughts...

One of the difficulties in tackling lock problems is that they are "racy" -- they're highly dependent on timing of concurrent operations. You may run some code several times by hand, and it works each time, but then it fails intermittently in production because the quantities and timings are different. It may help to use a tool like Apache "ab" or JMeter to generate a big batch of requests.

Quote from: JohnFF on January 14, 2015, 03:53:18 am

3) in our post hook, we recently inserted a "sleep(3)" command, in an attempt to prevent the inbound and return messages being created in the same second (this was making it hard to follow the order that messages happened in). Could this cause us problems with lots of messages flooding in at once? Is there a better way to achieve the same effect?

Are the inbound message (mobile-originated, MO) and outbound reply message (mobile-terminated, MT) generated by the same process (or thread or PHP-request-cycle) -- or by different processes? From the comments, it sounds like this pseudocode:

Code: [Select]

function onRecieveMO($mo) {
  recordActivity($mo);
  sleep(3);
  $mt = createResponse($mo);
  send($mt);
}

My guess: sleep(3) would either make no difference or make it worse. (I'm not certain which because it depends on how the critical sections work out.)

"Critical section" is a useful concept demonstrated by this snippet:

Code: [Select]

a();
acquireLock();
b(); // this is the "critical section" after acquiring the lock but before releasing the lock
releaseLock();
c();

Lock problems can only arise when 2+ concurrent processes want to run the critical section at the same time. If the critical section is long, then it increases the odds of contention. Plopping sleep(3) into the critical-section would exacerbate the problem. However, plopping sleep(3) outside the critical section would have no affect.

(Aside: There *are* some common tricks related to locking and sleep() - but generally that involves some repetition and randomization. For example: When acquiring a lock, you might make up to ten attempts; and each attempt might be spread out at a random interval between 100ms-400ms.)

Of course, that's theory. To apply it, one needs to identify the critical-section, and that's a PITA because many of the locks are acquired and released *implicitly*. You basically need to dump the SQL log for each process and identify queries that have some relevance to locking (e.g. BEGIN, COMMIT, SELECT FOR UPDATE, UPDATE).

The advice from http://dev.mysql.com/doc/refman/5.0/en/innodb-deadlocks.html is to write your code in a way which will retry following a deadlock. I haven't written code which does that before, but it sounds something like this pseudocode:

Code: [Select]

  public function onReceiveMO($mo) {
    $attempts = 0;
    while ($attempts < MAX_ATTEMPTS) {
      $attempts++;
      try {
        beginTransaction();
        doTheRealWork($mo);
        commitTransaction();
        return;
      } catch (DeadlockException $e) {
        rollbackTransaction();
        log("Encountered deadlock. Transaction aborted.");
        usleep(rand(MIN_WAIT, MAX_WAIT));
      }
      // Allow any other exceptions to propagate up
    }
    throw new Exception("Too many deadlocks. Giving up.", $e);
  }

To pursue this approach, we may need some patches to core to improve the reporting of deadlocks.

Quote from: michaelmcandrew

Any thoughts on JP's forum post on what pattern you might be able to use to queue stuff up, etc., or similar?

Using a queue is a good idea. For example, you might use this process:

When SMS gateway submits MO, push it into a queue.
In the background, a process monitors the queue.
The background process is responsible for saving MOs and sending response MTs.

The nice thing about this is that you can exercise very tight controls over concurrency. For example, suppose you want httpd/phpd to allow 20 concurrent requests (because that's good for most page-requests), but the SMS stuff may need to run with only 1 or 2 concurrent requests. You just move the requests to the queue and configure the #queue workers at a desired level.

(Aside: The actual implementation requires more discussion that - but that's the high-level. I could write a book on the subject of background processing for Civi ... *ahem* https://docs.google.com/document/d/16256_JwdqfDAy5v-b-6BkLbW8pWWFFtJa0hBBWa8CPA/edit?usp=sharing ).

DaveFF · January 15, 2015, 04:19:32 am

You're quite close with the pseudocode above. The function below is called from the post hook in the chain SMS extension, for "Inbound SMS" activities. So the outbound/MT is sent within the post hook for the inbound/MO, which is triggered by CRM_SMS_Provider::processInbound saving the inbound activity when it comes in from Clickatell.

The sleep wasn't added to fix deadlocks, it was to fix ordering. I wanted the outbound to always show after the inbound when sorted by date/time, which it sometimes didn't when they were recorded at exactly the same second.

Code: [Select]

/**
 * Respond to inbound SMS, if applicable, through the chain system.
 * Part of a hook_civicrm_post implementation.
 */
function chainsms_post_respond_to_inbound_sms($op, $objectName, $objectId, &$objectRef) {
  $activity = civicrm_api('Activity', 'getsingle', array('version' => '3', 'id' => $objectId));
  if (civicrm_error($activity)) {
    CRM_Core_Error::debug_log_message("In chainsms_post_respond_to_inbound_sms: getsingle Activity id '$objectId' failed");
    return;
  }

  $p = new CRM_Chainsms_Processor;
  // This delay is because outbound/delivery activities from the chain were
  // getting the exact same date/time as the inbound, and sometimes showing
  // before the inbound in lists, which didn't make sense.
  sleep(3);
  $p->inbound($activity);
}

JohnFF · January 15, 2015, 10:22:26 am

In terms of our "next actions" (this is the new "highest priority", but obviously we need to put in a solution that lasts), I'd like to try

a) this queuing.
b) documenting the heck out of when things go wrong. At the moment the error logs that I have appear to be being truncated.

It seems to me that this queuing system would need be done not just in our chain sms, but at a far deeper level in the CiviCore.

The problem is that neither of us are familiar with this part of the codebase. Where should we even begin to implement something like this? (I'm asking rather than trying to track it down myself because reckless gung ho-ness is the mother of all mess ups).

totten · January 15, 2015, 01:48:38 pm

Quote from: DaveFF on January 15, 2015, 04:19:32 am

The sleep wasn't added to fix deadlocks, it was to fix ordering. I wanted the outbound to always show after the inbound when sorted by date/time, which it sometimes didn't when they were recorded at exactly the same second.

Ok, that's makes more sense.

You might have considered this already, but (as due diligence) how hard would it be to patch the code which records the SMS activity to allow customizing the activity_date_time? This would allow you to get the intended affect without a sleep() and without a major architectural change -- which may reduce the risk of deadlocks (by cutting the critical-section down from the 3+sec to <1sec).

If a direct patch is untenable for some reason, you might hack the time with CRM_Utils_Time. We do this in some unit-tests. It may or may not work -- depends on whether the underlying code uses CRM_Utils_Time::getTime*, time(), or something else. Based on a quick grep, CRM_Utils_Time::getTime* is outnumbered 2:1 by time().

Code: [Select]

CRM_Utils_Time::setTime('now +3sec');
$p->inbound($activity);
CRM_Utils_Time::resetTime();

totten · January 15, 2015, 02:10:37 pm

@JohnFF, let me think for a day before responding with more detailed thoughts about queuing.

JohnFF · January 16, 2015, 04:04:38 am

Thanks totten

Incidentally it emerges that we've experienced issues with deadlocking in other parts (our webform tracking survey). Again the logs aren't of too much help. I think that the 80 character limit defined in CRM/Core/Error.php is too low (we've upped it to 600 - is that likely to be high enough for data updating queries?).

It seems to me that we won't be the only people encountering similar issues, and so it's worth CiviCRM having a solution to the bug.

I've added the following bug: https://issues.civicrm.org/jira/browse/CRM-15833?filter=-2.

DaveFF · January 19, 2015, 01:34:08 am

Extending queuing sounds like a good idea, if it can be made to cover single messages too. Although the Mailing system has some queuing/throttling, when it's used with a chain survey such as ours the system can still come under load. I think it would be useful in this case to be able to assign priorities- for example, give chain responses higher priorities than the initial mass mailing, so contacts don't have to wait a long time for the next question until the whole mass mailing has gone out.

DaveFF · January 19, 2015, 01:42:04 am

Quote from: totten on January 15, 2015, 01:48:38 pm

Code: [Select]
CRM_Utils_Time::setTime('now +3sec'); $p->inbound($activity); CRM_Utils_Time::resetTime();

Thanks, that sounds just right. Would need a patch to CRM_Activity_BAO_Activity::sendSMS though which contains the line

Code: [Select]

'activity_date_time' => date('YmdHis'),

totten · January 20, 2015, 11:26:30 pm

Yup, exactly.

I've added some comments on JIRA.

DaveFF · January 21, 2015, 02:11:31 am

Having removed the sleep command, we sent out another batch of SMS surveys last night. Within a minute of the first reply coming in, before the mass SMS had finished sending, we were experiencing deadlocks on INSERT INTO civicrm_activity_contact, sometimes several deadlocks per minute.

DaveFF · January 21, 2015, 02:27:03 am

This looks like it may be similar to https://issues.civicrm.org/jira/browse/CRM-15470. Their issue is experienced with updates coming in from their payment processor- and deadlocks appearing on INSERT INTO civicrm_activity_contact.

totten · January 21, 2015, 07:03:41 pm

Quote from: DaveFF on January 21, 2015, 02:11:31 am

Having removed the sleep command, we sent out another batch of SMS surveys last night. Within a minute of the first reply coming in, before the mass SMS had finished sending, we were experiencing deadlocks on INSERT INTO civicrm_activity_contact, sometimes several deadlocks per minute.

That's quite interesting. More questions/speculation:

1. The per-minute rate of deadlocks went up -- do you think the total quantity or percentage of deadlocks went up, too?

2. When you get notifications from the SMS gateway, how many HTTP notifications would one expect for a given contact? For example, if the SMS integration provides delivery notifications, you might get one HTTP callback for delivery status of the MT -- and then a second HTTP callback for the MO. Or perhaps there are no MT callbacks?

3. Do you think the SMS callbacks might be concurrent with the blast? For example, perhaps process #1 initiates a blast to 1000 people; it sends the first SMS to Alice and proceeds to Bob, Carol, ad nauseum. However, while process #1 is still sending to Bob, we receive a delivery-notification or MO-notification about Alice, so process #2 kicks off. Perhaps process #2 attempts to acquire some locks related to Alice, but process #1 didn't release them, so we get a deadlock.

4. Some background thinking on #3: The conversation focused on the SMS-receive-respond logic because it was the part that appeared in the error log. But it takes two processes to deadlock, and you're not supposed to get deadlocks when two processes follow the same locking logic (which implies that SMS-receive-respond logic cannot deadlock with itself; it's not totally impossible if the logic is complex... but it's a rule-of-thumb). So it's an open-question about what the second-process is. The second process might be the blaster -- the blaster is a very tempting scapegoat. It feels more plausible than, say, webform. Why? Because the relation between webform and SMS-receive-respond is basically random, and it would be just as random with or without sleep(). However, the relationship between blaster and callback is *not* random - and sleep() could have a systemic effect on their relationship. Moreover, the blaster is a long process that deals with many records - both of which can drive up the odds of locking issues. (Aside: Are there other long-running processes that deal with many records concurrent with SMS blast?)

5. Are you able to simulate an SMS-blast with notifications on a local dev box?

DaveFF · January 23, 2015, 02:15:29 am

1. Haven't analysed this in detail, but I think there are spikes (more deadlocks than usual) associated with these surveys, and then (in the case above) it tailed off.

2. For MT, we make a HTTP request outbound. Looking at the code we'd then expect a delivery status callback inbound but I'm not sure we've got this enabled. For MO, just the one inbound request (possibly more if they send us a long message?)

3. Yes, definitely. We start getting replies, immediately sending out the next question to them, while the initial blast is still in progress.

5. We can simulate a conversation for the purpose of checking the chain SMS processor actually processes input and carries on a conversation. We don't have any means of simulating a blast locally.

CiviCRM Community Forums (archive)

News:

Author Topic: No Deadlock Handling (SMS Tracking Survey Extension) (Read 2719 times)

JohnFF

No Deadlock Handling (SMS Tracking Survey Extension)

DaveFF

Re: SMS Tracking Survey Extension

totten

Re: SMS Tracking Survey Extension

DaveFF

Re: SMS Tracking Survey Extension

JohnFF

Re: SMS Tracking Survey Extension

totten

Re: SMS Tracking Survey Extension

totten

Re: SMS Tracking Survey Extension

JohnFF

Re: SMS Tracking Survey Extension

DaveFF

Re: SMS Tracking Survey Extension

DaveFF

Re: SMS Tracking Survey Extension

totten

Re: No Deadlock Handling (SMS Tracking Survey Extension)

DaveFF

Re: No Deadlock Handling (SMS Tracking Survey Extension)

DaveFF

Re: No Deadlock Handling (SMS Tracking Survey Extension)

totten

Re: No Deadlock Handling (SMS Tracking Survey Extension)

DaveFF

Re: No Deadlock Handling (SMS Tracking Survey Extension)