Contact.create updating current_employer deadlocks against updating display_name

[DaveFF]

We are developing a custom front-end which will allow teachers to view and edit a much wider range of information about their current and former students than the current version. In the screenshot below there is an Employer field; on change, this issues a Contact.create call to update current_employer, which automatically creates a new organisation if it doesn't already exist. Sometimes the query that creates the new organisation deadlocks against a query that updates the display_name and sort_name of the student. I've included some information below, and I would appreciate any advice you can offer. Is this a bug?

Code: [Select]

$backTrace = #0 /var/www/html/prod/drupal-7.27/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.27/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2), Object(DB_Error))
#3 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/DB.php(969): PEAR_Error->PEAR_Error("DB Error: unknown error", -1, 16, (Array:2), "UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...")
#4 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/PEAR.php(564): DB_Error->DB_Error(-1, 16, (Array:2), "UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...")
#5 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/DB/common.php(1905): PEAR->raiseError(NULL, -1, NULL, NULL, "UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...", "DB_Error", TRUE)
#6 /var/www/html/prod/drupal-7.27/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.27/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError()
#8 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/DB/common.php(1216): DB_mysql->simpleQuery("UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...")
#9 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/DB/DataObject.php(2421): DB_common->query("UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...")
#10 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/packages/DB/DataObject.php(1324): DB_DataObject->_query("UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type =...")
#11 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Core/DAO.php(275): DB_DataObject->update()
#12 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Contact/BAO/Contact.php(218): CRM_Core_DAO->save()
#13 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Contact/BAO/Contact.php(314): CRM_Contact_BAO_Contact::add((Array:10))
#14 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/api/v3/Contact.php(380): CRM_Contact_BAO_Contact::create((Array:10))
#15 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/api/v3/Contact.php(102): _civicrm_api3_contact_update((Array:8), 111279)
#16 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/api/api.php(88): civicrm_api3_contact_create((Array:5))
#17 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Utils/REST.php(361): civicrm_api("Contact", "create", (Array:5))
#18 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Utils/REST.php(594): CRM_Utils_REST::process((Array:3), (Array:3))
#19 [internal function](): CRM_Utils_REST::ajax((Array:3))
#20 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Core/Invoke.php(289): call_user_func((Array:2), (Array:3))
#21 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Core/Invoke.php(72): CRM_Core_Invoke::runItem((Array:12))
#22 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke((Array:3))
#23 /var/www/html/prod/drupal-7.27/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke((Array:3))
#24 [internal function](): civicrm_invoke("ajax", "rest")
#25 /var/www/html/prod/drupal-7.27/includes/menu.inc(517): call_user_func_array("civicrm_invoke", (Array:2))
#26 /var/www/html/prod/drupal-7.27/index.php(21): menu_execute_active_handler()
#27 {main}


Code: [Select]

=====================================
140910 15:37:49 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 43 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2251 1_second, 2251 sleeps, 209 10_second, 216 background, 216 flush
srv_master_thread log flush and writes: 2392
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 752, signal count 1778
Mutex spin waits 3991, rounds 14106, OS waits 283
RW-shared spins 594, rounds 13181, OS waits 360
RW-excl spins 110, rounds 4989, OS waits 95
Spin rounds per wait: 3.53 mutex, 22.19 RW-shared, 45.35 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
140910 15:19:04
*** (1) TRANSACTION:
TRANSACTION 1FCCCF, ACTIVE 1 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1248, 5 row lock(s), undo log entries 2
MySQL thread id 839, OS thread handle 0x7f90343d5700, query id 185042 localhost root
INSERT INTO civicrm_contact (contact_type , contact_sub_type , sort_name , display_name , preferred_language , hash , addressee_id , organization_name ) VALUES ('Organization' ,  NULL , 'test employer zzzq' , 'test employer zzzq' , 'en_US' , '68afae65c6883b95e51ed8fbbcadbae5' ,  3 , 'test employer zzzq' )
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3289 n bits 600 index `index_organization_name` of table `future_civicrm`.`civicrm_contact` trx id 1FCCCF lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 527 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 18; hex 7465737420656d706c6f796572207a7a7a7a; asc test employer zzzz;;
 1: len 4; hex 0001d1f6; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 1FCCD1, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
6 lock struct(s), heap size 1248, 3 row lock(s)
MySQL thread id 838, OS thread handle 0x7f9034499700, query id 185069 localhost root Updating
UPDATE  civicrm_contact  SET contact_type = 'Individual' , contact_sub_type = '
Student
' , sort_name = 'Student, Jim' , display_name = 'Jim Student'   WHERE (  civicrm_contact.id = 111279 )
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 3289 n bits 600 index `index_organization_name` of table `future_civicrm`.`civicrm_contact` trx id 1FCCD1 lock mode S locks gap before rec
Record lock, heap no 527 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 18; hex 7465737420656d706c6f796572207a7a7a7a; asc test employer zzzz;;
 1: len 4; hex 0001d1f6; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 201034 n bits 144 index `PRIMARY` of table `future_civicrm`.`civicrm_contact` trx id 1FCCD1 lock_mode X locks rec but not gap waiting
Record lock, heap no 75 PHYSICAL RECORD: n_fields 52; compact format; info bits 0
 0: len 4; hex 0001b2af; asc     ;;
 1: len 6; hex 0000001fccb5; asc       ;;
 2: len 7; hex 22000018eb1bda; asc "      ;;
 3: len 10; hex 496e646976696475616c; asc Individual;;
 4: len 9; hex 0153747564656e7401; asc  Student ;;
 5: len 1; hex 80; asc  ;;
 6: len 1; hex 80; asc  ;;
 7: len 1; hex 80; asc  ;;
 8: len 1; hex 80; asc  ;;
 9: len 1; hex 80; asc  ;;
 10: len 1; hex 80; asc  ;;
 11: SQL NULL;
 12: SQL NULL;
 13: len 12; hex 53747564656e742c204a696d; asc Student, Jim;;
 14: len 11; hex 4a696d2053747564656e74; asc Jim Student;;
 15: SQL NULL;
 16: SQL NULL;
 17: SQL NULL;
 18: SQL NULL;
 19: len 5; hex 656e5f5553; asc en_US;;
 20: len 1; hex 03; asc  ;;
 21: len 30; hex 653666363566333866613336613335646438313539303165383435396435; asc e6f65f38fa36a35dd815901e8459d5; (total 32 bytes);
 22: SQL NULL;
 23: len 14; hex 53747564656e74207369676e7570; asc Student signup;;
 24: len 3; hex 4a696d; asc Jim;;
 25: SQL NULL;
 26: len 7; hex 53747564656e74; asc Student;;
 27: SQL NULL;
 28: SQL NULL;
 29: len 4; hex 00000001; asc     ;;
 30: SQL NULL;
 31: len 8; hex 44656172204a696d; asc Dear Jim;;
 32: len 4; hex 00000001; asc     ;;
 33: SQL NULL;
 34: len 8; hex 44656172204a696d; asc Dear Jim;;
 35: len 4; hex 00000001; asc     ;;
 36: SQL NULL;
 37: len 11; hex 4a696d2053747564656e74; asc Jim Student;;
 38: SQL NULL;
 39: SQL NULL;
 40: len 3; hex 8f8223; asc   #;;
 41: len 1; hex 80; asc  ;;
 42: SQL NULL;
 43: SQL NULL;
 44: SQL NULL;
 45: len 17; hex 7465737420656d706c6f796572207a7a7a; asc test employer zzz;;
 46: SQL NULL;
 47: SQL NULL;
 48: len 4; hex 0001d1f5; asc     ;;
 49: len 1; hex 80; asc  ;;
 50: len 4; hex 53da029c; asc S   ;;
 51: len 4; hex 54105dcf; asc T ] ;;

*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 1FCD62
Purge done for trx's n:o < 1FCD62 undo n:o < 0
History list length 1600
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 564, OS thread handle 0x7f9034468700, query id 185775 localhost root
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
81235 OS file reads, 31432 OS file writes, 7282 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.23 writes/s, 0.16 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7, 302 merges
merged operations:
 insert 377, delete mark 5081, delete 227
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 276707, node heap has 518 buffer(s)
0.02 hash searches/s, 0.60 non-hash searches/s
---
LOG
---
Log sequence number 34422262411
Log flushed up to   34422262411
Last checkpoint at  34422262411
0 pending log writes, 0 pending chkp writes
6269 log i/o's done, 0.07 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 9965097
Buffer pool size   8192
Free buffers       1
Database pages     7673
Old database pages 2812
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 90063, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 81224, created 3953, written 24475
0.00 reads/s, 0.00 creates/s, 0.12 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 7673, unzip_LRU len: 0
I/O sum[5]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 1482, id 140257033914112, state: waiting for server activity
Number of rows inserted 10937, updated 5434, deleted 12607, read 14704912
0.00 inserts/s, 0.02 updates/s, 0.00 deletes/s, 0.44 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================