Change Log Tab Excrutiatingly Slow - Poorly Performing Query and Fix (from 8 minutes down to 4 seconds)
The page takes about 8 minutes to return which is absurdly slow for anything expected to be remotely interactive. It is so slow that my client is referring to it as the "Triangle of Doom".
I tracked it down to this query:
INSERT IGNORE INTO civicrm_tmp_e_logsummary_ffa3ac146126d178ade367f2a5d17bf5
SELECT activity_id, IF (entity_log_civireport.log_action = 'Insert' AND extra_table.activity_type_id = 51 , GROUP_CONCAT(entity_log_civireport.contact_id), 1) , entity_log_civireport.log_action as log_civicrm_entity_log_action, 'log_civicrm_activity_contact' as log_civicrm_entity_log_type, entity_log_civireport.log_user_id as log_civicrm_entity_log_user_id, entity_log_civireport.log_date as log_civicrm_entity_log_date, modified_contact_civireport.display_name as log_civicrm_entity_altered_contact, modified_contact_civireport.id as log_civicrm_entity_altered_contact_id, entity_log_civireport.log_conn_id as log_civicrm_entity_log_conn_id, modified_contact_civireport.is_deleted as log_civicrm_entity_is_deleted, altered_by_contact_civireport.display_name as altered_by_contact_display_name
FROM staging_civicrm.log_civicrm_activity_contact entity_log_civireport
JOIN civicrm_contact modified_contact_civireport ON (entity_log_civireport.contact_id = modified_contact_civireport.id )
JOIN staging_civicrm.log_civicrm_activity extra_table ON extra_table.id = entity_log_civireport.activity_id
LEFT JOIN civicrm_contact altered_by_contact_civireport ON (entity_log_civireport.log_user_id = altered_by_contact_civireport.id)
WHERE modified_contact_civireport.id = 338520 AND
entity_log_civireport.log_action != 'Initialization'
GROUP BY entity_log_civireport.log_conn_id,
entity_log_civireport.log_user_id,
EXTRACT(DAY_MICROSECOND FROM entity_log_civireport.log_date),
entity_log_civireport.id
ORDER BY entity_log_civireport.log_date DESC;
EXPLAIN shows:
+------+-------------+-------------------------------+--------+---------------+---------+---------+---------------------------------------------------+---------+-------------------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------------------------------+--------+---------------+---------+---------+---------------------------------------------------+---------+-------------------------------------------------+
| 1 | SIMPLE | modified_contact_civireport | const | PRIMARY | PRIMARY | 4 | const | 1 | Using temporary; Using filesort |
| 1 | SIMPLE | extra_table | ALL | NULL | NULL | NULL | NULL | 3014020 | |
| 1 | SIMPLE | entity_log_civireport | ALL | NULL | NULL | NULL | NULL | 5518537 | Using where; Using join buffer (flat, BNL join) |
| 1 | SIMPLE | altered_by_contact_civireport | eq_ref | PRIMARY | PRIMARY | 4 | staging_civicrm.entity_log_civireport.log_user_id | 1 | Using where |
+------+-------------+-------------------------------+--------+---------------+---------+---------+---------------------------------------------------+---------+-------------------------------------------------+
The fix passes:
First pass:
ALTER TABLE log_civicrm_activity_contact ADD INDEX index_activity_id (activity_id);
With no further changes, this alone makes the above query go from 8 minutes to 1m45s.
Explain plain:
+------+-------------+-------------------------------+--------+-------------------+-------------------+---------+---------------------------------------------------+---------+---------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------------------------------+--------+-------------------+-------------------+---------+---------------------------------------------------+---------+---------------------------------+
| 1 | SIMPLE | modified_contact_civireport | const | PRIMARY | PRIMARY | 4 | const | 1 | Using temporary; Using filesort |
| 1 | SIMPLE | extra_table | ALL | NULL | NULL | NULL | NULL | 3014020 | Using where |
| 1 | SIMPLE | entity_log_civireport | ref | index_activity_id | index_activity_id | 5 | staging_civicrm.extra_table.id | 1 | Using where |
| 1 | SIMPLE | altered_by_contact_civireport | eq_ref | PRIMARY | PRIMARY | 4 | staging_civicrm.entity_log_civireport.log_user_id | 1 | Using where |
+------+-------------+-------------------------------+--------+-------------------+-------------------+---------+---------------------------------------------------+---------+---------------------------------+
Second pass:
ALTER TABLE log_civicrm_activity ADD INDEX index_id (id);
Change the JOIN order explicitly and add a hint for the query optimizer to not re-order the JOINs:
SELECT STRAIGHT_JOIN activity_id, IF (entity_log_civireport.log_action = 'Insert' AND extra_table.activity_type_id = 51 , GROUP_CONCAT(entity_log_civireport.contact_id), 1) , entity_log_civireport.log_action as log_civicrm_entity_log_action, 'log_civicrm_activity_contact' as log_civicrm_entity_log_type, entity_log_civireport.log_user_id as log_civicrm_entity_log_user_id, entity_log_civireport.log_date as log_civicrm_entity_log_date, modified_contact_civireport.display_name as log_civicrm_entity_altered_contact, modified_contact_civireport.id as log_civicrm_entity_altered_contact_id, entity_log_civireport.log_conn_id as log_civicrm_entity_log_conn_id, modified_contact_civireport.is_deleted as log_civicrm_entity_is_deleted, altered_by_contact_civireport.display_name as altered_by_contact_display_name
FROM civicrm_contact modified_contact_civireport
JOIN staging_civicrm.log_civicrm_activity_contact entity_log_civireport ON entity_log_civireport.contact_id = modified_contact_civireport.id
JOIN staging_civicrm.log_civicrm_activity extra_table ON extra_table.id = entity_log_civireport.activity_id
LEFT JOIN civicrm_contact altered_by_contact_civireport ON entity_log_civireport.log_user_id = altered_by_contact_civireport.id
WHERE modified_contact_civireport.id = 338520 AND
entity_log_civireport.log_action != 'Initialization'
GROUP BY entity_log_civireport.log_conn_id,
entity_log_civireport.log_user_id,
EXTRACT(DAY_MICROSECOND FROM entity_log_civireport.log_date),
entity_log_civireport.id
ORDER BY entity_log_civireport.log_date DESC;
New EXPLAIN:
+------+-------------+-------------------------------+--------+-------------------+----------+---------+---------------------------------------------------+---------+---------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------------------------------+--------+-------------------+----------+---------+---------------------------------------------------+---------+---------------------------------+
| 1 | SIMPLE | modified_contact_civireport | const | PRIMARY | PRIMARY | 4 | const | 1 | Using temporary; Using filesort |
| 1 | SIMPLE | entity_log_civireport | ALL | index_activity_id | NULL | NULL | NULL | 5518537 | Using where; Using filesort |
| 1 | SIMPLE | extra_table | ref | index_id | index_id | 5 | staging_civicrm.entity_log_civireport.activity_id | 1 | |
| 1 | SIMPLE | altered_by_contact_civireport | eq_ref | PRIMARY | PRIMARY | 4 | staging_civicrm.entity_log_civireport.log_user_id | 1 | Using where |
+------+-------------+-------------------------------+--------+-------------------+----------+---------+---------------------------------------------------+---------+---------------------------------+
This gets it down to 4 seconds!
Since the first index we started with is no longer getting used in the final variant, we can just not add it.
Summary:
To fix "Change Log" tab taking forever to load, the following fix is needed:
Add index:
ALTER TABLE log_civicrm_activity ADD INDEX index_id (id);
Make the code emit the query modified as follows:
INSERT IGNORE INTO civicrm_tmp_e_logsummary_ffa3ac146126d178ade367f2a5d17bf5
SELECT STRAIGHT_JOIN activity_id, IF (entity_log_civireport.log_action = 'Insert' AND extra_table.activity_type_id = 51 , GROUP_CONCAT(entity_log_civireport.contact_id), 1) , entity_log_civireport.log_action as log_civicrm_entity_log_action, 'log_civicrm_activity_contact' as log_civicrm_entity_log_type, entity_log_civireport.log_user_id as log_civicrm_entity_log_user_id, entity_log_civireport.log_date as log_civicrm_entity_log_date, modified_contact_civireport.display_name as log_civicrm_entity_altered_contact, modified_contact_civireport.id as log_civicrm_entity_altered_contact_id, entity_log_civireport.log_conn_id as log_civicrm_entity_log_conn_id, modified_contact_civireport.is_deleted as log_civicrm_entity_is_deleted, altered_by_contact_civireport.display_name as altered_by_contact_display_name
FROM civicrm_contact modified_contact_civireport
JOIN staging_civicrm.log_civicrm_activity_contact entity_log_civireport ON entity_log_civireport.contact_id = modified_contact_civireport.id
JOIN staging_civicrm.log_civicrm_activity extra_table ON extra_table.id = entity_log_civireport.activity_id
LEFT JOIN civicrm_contact altered_by_contact_civireport ON entity_log_civireport.log_user_id = altered_by_contact_civireport.id
WHERE modified_contact_civireport.id = 338520 AND
entity_log_civireport.log_action != 'Initialization'
GROUP BY entity_log_civireport.log_conn_id,
entity_log_civireport.log_user_id,
EXTRACT(DAY_MICROSECOND FROM entity_log_civireport.log_date),
entity_log_civireport.id
ORDER BY entity_log_civireport.log_date DESC;
Not only does this speed it up from 8 minutes down to 4 seconds, it also doesn't wreak havoc with row locking where every row scanned gets locked by the transaction engine, potentially resulting in a massive query pile-up in the database.