Fixed Catastrophically poor performance when viewing "IP" dialog & in approval queue

[Xon]

Affected version

2.2.8 Patch 1

While the "Delete IP usage data after" option does help, MySQL can still pick the utterly wrong indexes which can result in very bad performance.

In the IP dialog, and the approval queue, \XF\Entity\User::getIp calls XF\Repository\IP::getLoggedIp which then triggers this query;

SELECT ip
FROM xf_ip
WHERE content_type = 'user'
        AND content_id = 'xxx'
        AND action = 'register'
ORDER BY log_date DESC
LIMIT 1;

However the indexes for the table are;

$table->addKey(['user_id', 'log_date']);
$table->addKey(['ip', 'log_date']);
$table->addKey(['content_type', 'content_id']);
$table->addKey('log_date');

The content_type_content_id index is good enough, but log_date absolutely needs to be avoided as this will result in multiple full-table scan when viewing the approval queue.

user_id_log_date would need the user_id to be sent to getLoggedIp (or for getLoggedIp to be smart enough to set user_id when doing content_type = 'user')

 

[Mr. Jinx]

I noticed the same issue some time ago.
As a workaround I also deleted the old IP data (which is probably good for GDPR compliance anyway). This seems to explain the behavior.

 

[Xon]

I actually hit this issue ages ago back in XF1, but never tracked it down to just simple bad index choices.

 

[loulou]

I suffer this issue since XF1.5 once my approval queue list hits ~500+ items. This is extremely long to load.

 

[VersoBit]

I can confirm we experience the same slowness on this query at Fellowsfilm (and with a few of our clients who run XenForo).

 

[Jeremy P]

@Xon Can you confirm whether adding the user_id clause results in MySQL picking the correct index?

SELECT ip
FROM xf_ip
WHERE content_type = 'user'
	AND content_id = 'xxx'
	AND action = 'register'
	AND user_id = 'xxx'
ORDER BY log_date DESC
LIMIT 1

 

[Xon]

Still catastrophically poor performance. I've started a conversation with additional details.

Adding the user_id isn't enough, at least with MariaDB 10.3.x (which is one of the older stable branches but still supported)

 

[XF Bug Bot]

Thank you for reporting this issue, it has now been resolved. We are aiming to include any changes that have been made in a future XF release (2.2.10).

Change log:

Pass an index hint when performing certain IP lookups

There may be a delay before changes are rolled out to the XenForo Community.

 

[Neilski]

While the "Delete IP usage data after" option does help, MySQL can still pick the utterly wrong indexes which can result in very bad performance.

I've experienced this but was never really able to fully understand quite why it was so awful, despite conducting some tests on an offline copy of the table. (Plenty of "explains" and head-scratching ensued, but no dice.)

The content_type_content_id index is good enough, but log_date absolutely needs to be avoided as this will result in multiple full-table scan when viewing the approval queue.

Yup, multiple full-table scans were the only way to explain the shocking performance.

I'm obviously delighted that the system performance should now be much improved with the patch.
However, I'd love to get a proper understanding of why it was so bad - if you or anyone can explain, or just point me at info to help me understand this, I'd be very grateful. (I spent quite a while googling for info, but didn't really find what I was after.)

 

[Xon]

However, I'd love to get a proper understanding of why it was so bad - if you or anyone can explain, or just point me at info to help me understand this, I'd be very grateful. (I spent quite a while googling for info, but didn't really find what I was after.)

XenForo used to log a lot of login events under content_type = 'user' and content_id =? which resulted in the statistics for these columns to get very useless for this query. Worse, that index is very wide, so MySQL tends to try to avoid it.

 

[Neilski]

XenForo used to log a lot of login events under content_type = 'user' and content_id =? which resulted in the statistics for these columns to get very useless for this query. Worse, that index is very wide, so MySQL tends to try to avoid it.

Thanks. If I recall correctly, I was seeing crazy query durations even when the 'explain' seemed to indicate that it wouldn't try to use an index.
Naively, I'd have expected that if no index was being used, the very worst-case scenario would be a single pass through the table, but nope.
Is there a good place to learn more about how pathological stuff happens, and how to avoid it?