Change Log Tab Excrutiatingly Slow - Poorly Performing Query and Fix (from 8 minutes down to 4 seconds)

Question

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                                     |
+------+-------------+-------------------------------+--------+---------------+---------+---------+---------------------------------------------------+---------+-------------------------------------------------+

Answer 1

The fix passes:

1. 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                     |
+------+-------------+-------------------------------+--------+-------------------+-------------------+---------+---------------------------------------------------+---------+---------------------------------+

2. 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:

1. Add index:

ALTER TABLE log_civicrm_activity ADD INDEX index_id (id);

2. 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.