CiviCRM Community Forums (archive)

Our site has been massively slow the last week. I've been trying to diagnose, and I started logging slow queries.

I notice that virtually all of them are something similar to this:

# Query_time: 50.578224  Lock_time: 0.003810 Rows_sent: 0  Rows_examined: 4
SET timestamp=1382576552;
INSERT INTO civicrm_acl_contact_cache ( user_id, contact_id, operation)
SELECT 449661 as user_id,  contact_a.id as contact_id, 'View' as operation
FROM civicrm_contact contact_a
LEFT JOIN civicrm_value_additional_individual_informatio_1 ON contact_a.id = civicrm_value_additional_individual_informatio_1.entity_id  LEFT JOIN civicrm_value_household_information_41 ON contact_a.id = civicrm_value_household_information_41.entity_id
WHERE ( 1 ) 
AND (civicrm_value_additional_individual_informatio_1.chapter_282 IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20)
OR civicrm_value_additional_individual_informatio_1.commissions_8 IN (1,2,3)
OR civicrm_value_household_information_41.chapter_2013_281 IN (1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20)
OR contact_type='Organization')
AND (contact_a.is_deleted = 0)
GROUP BY contact_a.id
ON DUPLICATE KEY UPDATE
         user_id=VALUES(user_id)
         contact_id=VALUES(contact_id)
         operation=VALUES(operation);
# User@Host: civi[civi] @ localhost []
They are always about 50s long. I have little to no idea what acl_contact_cache is doing. We do use some CiviCRM ACLs, as well as some custom stuff in a acl hook, but that has been in place fo 2 years and hasn't changed.

Any thoughts?

xavier: do u have any specific issue numbers or work in 4.4 that impacted acls

lobo

I can't upgrade to 4.4 at the moment as this is a production site and I need to do some testing.

I don't see how this relates to smart groups from the code above. Am I missing something?

Brian

am curious, was that a custom search generating that query and/or acl hooks?

lobo

I'm also noticing the below error a lot in our general mysql log which I have enabled. Commas are missing as I copied and pasted it from an excel spreadsheet!

I can see that the acl_contact_cache INSERT seems to be failing due to a lock wait timeout (see #6). Not sure what would be causing that, but that error has been popping up a lot on manual mysql queries I do since things started slowing down.   

I may do an upgrade from 4.3.5 to 4.3.7. I find that sometimes a fresh set of code in there fixes some of the mysterious ailments that develop over time, but I'd prefer to find a answer

131024  1:02:59    82 Query INSERT INTO watchdog (uid" type message variables severity link location referer hostname timestamp) VALUES ('8' 'civicrm' '$backTrace =
#0 /persistent/html/sites/all/modules/civicrm/CRM/Core/Error.php(751): CRM_Core_Error::backtrace(\"backTrace\" TRUE)\n
#1 [internal function](): CRM_Core_Error::exceptionHandler(Object(DB_Error))\n
#2 /persistent/html/sites/all/modules/civicrm/packages/PEAR.php(931): call_user_func((Array:2) Object(DB_Error))\n
#3 /persistent/html/sites/all/modules/civicrm/packages/DB.php(969): PEAR_Error->PEAR_Error(\"DB Error: unknown error\" -1 16 (Array:2) \"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#4 /persistent/html/sites/all/modules/civicrm/packages/PEAR.php(564): DB_Error->DB_Error(-1 16 (Array:2) \"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#5 /persistent/html/sites/all/modules/civicrm/packages/DB/common.php(1905): PEAR->raiseError(NULL -1 NULL NULL \"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\" \"DB_Error\" TRUE)\n
#6 /persistent/html/sites/all/modules/civicrm/packages/DB/mysql.php(898): DB_common->raiseError(-1 NULL NULL NULL \"1205 ** Lock wait timeout exceeded; try restarting transaction\")\n
#7 /persistent/html/sites/all/modules/civicrm/packages/DB/mysql.php(327): DB_mysql->mysqlRaiseError()\n
#8 /persistent/html/sites/all/modules/civicrm/packages/DB/common.php(1216): DB_mysql->simpleQuery(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#9 /persistent/html/sites/all/modules/civicrm/packages/DB/DataObject.php(2436): DB_common->query(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#10 /persistent/html/sites/all/modules/civicrm/packages/DB/DataObject.php(1613): DB_DataObject->_query(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#11 /persistent/html/sites/all/modules/civicrm/CRM/Core/DAO.php(155): DB_DataObject->query(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#12 /persistent/html/sites/all/modules/civicrm/CRM/Core/DAO.php(917): CRM_Core_DAO->query(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\" TRUE)\n
#13 /persistent/html/sites/all/modules/civicrm/CRM/Contact/BAO/Contact/Permission.php(143): CRM_Core_DAO::executeQuery(\"\\nINSERT INTO civicrm_acl_contact_cache ( user_id contact_id operation )\\nS...\")\n
#14 /persistent/html/sites/all/modules/civicrm/CRM/Contact/BAO/Contact/Permission.php(216): CRM_Contact_BAO_Contact_Permission::cache(\"449661\")\n
#15 /persistent/html/sites/all/modules/civicrm/api/v3/Contact.php(640): CRM_Contact_BAO_Contact_Permission::cacheClause(\"cc\")\n
#16 /persistent/html/sites/all/modules/civicrm/api/api.php(75): civicrm_api3_contact_getquick((Array:6))\n#17 /persistent/html/sites/all/modules/civicrm/CRM/Contact/Page/AJAX.php(87): civicrm_api(\"Contact\" \"getquick\" (Array:6))\n
#18 [internal function](): CRM_Contact_Page_AJAX::getContactList((Array:11))\n
#19 /persistent/html/sites/all/modules/civicrm/CRM/Utils/REST.php(329): call_user_func((Array:2) (Array:11))\n
#20 /persistent/html/sites/all/modules/civicrm/CRM/Utils/REST.php(580): CRM_Utils_REST::process((Array:1) FALSE)\n
#21 [internal function](): CRM_Utils_REST::ajax((Array:3))\n
#22 /persistent/html/sites/all/modules/civicrm/CRM/Core/Invoke.php(257): call_user_func((Array:2) (Array:3))\n
#23 /persistent/html/sites/all/modules/civicrm/CRM/Core/Invoke.php(70): CRM_Core_Invoke::runItem((Array:12))\n
#24 /persistent/html/sites/all/modules/civicrm/CRM/Core/Invoke.php(52): CRM_Core_Invoke::_invoke((Array:3))\n
#25 /persistent/html/sites/all/modules/civicrm/drupal/civicrm.module(436): CRM_Core_Invoke::invoke((Array:3))\n
#26 [internal function](): civicrm_invoke(\"ajax\" \"rest\")\n
#27 /persistent/html/includes/menu.inc(517): call_user_func_array(\"civicrm_invoke\" (Array:2))\n
#28 /persistent/html/index.php(21): menu_execute_active_handler()\n#29 {main}\n' 'N;' '7' '' 'https://www.example.ca/civicrm/ajax/rest?className=CRM_Contact_Page_AJAX&fnName=getContactList&json=1&context=navigation&s=bernard%2C+sha&limit=10&timestamp=1382576527430&fieldName=&tableName=cc' 'https://www.example.ca/civicrm/contact/view?reset=1&cid=68710&key=478cd6c6f08f58b6d8515ff0cdd7e890_2587&context=advanced' '198.164.210.69' '1382576579')                                                                                                                                                                                                                                                                                                                                                                                                                                                 

I'm going to get 4.4 on a test site tonight and see what happens.

If this work is ongoing I can probably get some additional funds for more work.