1

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

6
  • This sounds great! Will this also help with very slow loading of individual change log entries or is that a separate issue? – Lars SG May 3 at 1:04
  • @LarsSG, not sure, haven't got that far yet. It's difficult to debug things beyond the first step when the first step takes 8 minutes to respond. – Gordan Bobic May 3 at 4:31
  • You might also want to have a look at this question and @eileen's solution there. Seems there are other tables that benefit from indexes as well. civicrm.stackexchange.com/questions/7645/… – Lars SG May 3 at 11:53
  • Yes, but in this case tables are already InnoDB and indexes alone only provide a 6x speed-up, not the further 20x speed-up on top of that. I already raised a similar issue here: civicrm.stackexchange.com/questions/39421/… – Gordan Bobic May 3 at 12:12
  • Please create a lab issue at lab.civicrm.org/dev/core/-/issues - and ideally a PR as well. – Aidan May 4 at 9:07

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.