Tons of FORCE INDEX (index_idsite_idvisitor) MySQL queries killing Matomo

[L3on1d]

Hi!

We have pretty high volume traffic sites, ~ 2 weeks ago we upgraded our DB server from MariaDB 10.5 to 10.6, last week Matomo was upgraded to v4.14.2, after that we start facing new issue.

System info:

OS: Ubuntu 18.04.6 LTS Matomo: 4.14.2 PHP: 8.0.28 DB: 10.6.12-MariaDB

Symptoms:

Once per day our MySQL server becomes unavailable due to tons of queries:

_"SELECT visit_last_action_time, visit_first_action_time, idvisitor, idvisit, user_id, visit_exit_idaction_url, visit_exit_idaction_name, visitor_returning, visitor_seconds_since_first, visitor_seconds_since_order, visitor_count_visits, visit_goal_buyer, location_country, location_region, location_city, location_latitude, location_longitude, referer_name, referer_keyword, referer_type, idsite, profilable, visit_entry_idaction_url, visit_total_actions, visit_total_interactions, visit_total_searches, referer_url, config_browser_name, config_client_type, config_device_brand, config_device_model, config_device_type, visit_total_events, visit_total_time, location_ip, location_browser_lang, last_idlink_va, custom_dimension_1, custom_dimension_2, custom_dimension_3, custom_dimension_4, custom_dimension_5, custom_var_k1, custom_var_v1, custom_var_k2, custom_var_v2, custom_var_k3, custom_var_v3, custom_var_k4, custom_var_v4, custom_var_k5, custom_var_v5 FROM mtm_log_visit FORCE INDEX (index_idsite_idvisitor) WHERE idsite = '1' AND visit_last_action_time <= '2023-04-27 00:48:29' AND idvisitor = 'E6???$?'\n ORDER BY visit_last_actiontime DESC\n LIMIT 1"

Btw, I found this old topic possible related to our problem - https://github.com/matomo-org/matomo/issues/16904 We have tried this config option - "To workaround this performance issue set [Tracker]enable_userid_overwrites_visitorid=0 in your config/config.ini.php" with no luck. :(

Any help would be appreciated, thank you!

[L3on1d]

Since we don't use userid feature, I think we need try to adjust a database index described in this article.

[michalkleiner]

Hi @L3on1d, thanks for raising the issue. It seems like you're on a good path there. Adding the custom index (which will be the default in Matomo 5) would be the next step I'd recommend trying here. Give it a go and let us know here if it helped?

[L3on1d]

Hi! Just changed database index, I will update you about results. Thank you.

[L3on1d]

Hi! @michalkleiner unfortunately we still facing same issue (occurs every day at 1:00 am UTC) after database index change. :/

[michalkleiner]

If it's everyday at the same time perhaps it's caused by something else and the Matomo queries are not related? Is there any other cron or other event running at the same time? Could it be that the new version of MariaDB is configured differently? We'd like to be of more help but this seems like a specific setup related issue rather than Matomo specific as we don't have any other reports relating to the same version of Matomo.

[L3on1d]

@michalkleiner Yes, It's weird, but I can confirm that we don't have any cron scheduled at that time, also I'm always exporting MySQL process list during this issue and it always full of _mtm_log_visit FORCE INDEX (index_idsiteidvisitor) queries. It looks for me like some internal Matomo process like old visitor logs deletion process (we keep raw logs data for 1 day only) which starts by Matomo every day ~ at the same time between 00:45-1:15 am. (according to MySQL monitoring) without any additional cron jobs. Is it possible that this issue occurs because Matomo deleting old logs and performing force index queries at the same time (mtm_log_visit table is used in both queries)? Thank you!

[michalkleiner]

I'm not that familiar with the background processes that could be going on based on scheduled/automated events or triggered by user visits, @bx80 could you think of anything to try here?

[L3on1d]

I can confirm that problem occurs during old raw logs deletion.

[bx80]

@L3on1d There was a change to the log deletion code which was released in 4.14.0, it's possible that this could be related to the performance issue you are now seeing.

It can be hard for us to recreate performance issues like this which can be dependent on vagaries in data and server configuration.

If you're comfortable temporarily patching a file on your installation, then one option to confirm this would be to revert the change (which is only a few lines) and then see if that fixes the problem.

[L3on1d]

@bx80 yes, please. Could you please provide instructions? Thank you!

[michalkleiner]

Hi @L3on1d, the change linked is https://github.com/matomo-org/matomo/pull/20424/files?diff=split&w=0 and what needs to be done is undo it temporarily in your local installation. You'd need to find the DataSubjects.php file in plugins/PrivacyManager/Model/ folder and find the lines that are in the green (right) side and replace them with the fewer lines from the red (left) side. Only attempt this if you know what you're doing and feel comfortable doing that, otherwise you could break your whole Matomo installation. Also make a backup copy of the file before attempting to modify it to be able to restore it if needed.

[L3on1d]

@michalkleiner thank you, I changed code regarding your instructions, but problem still exists, I'm thinking about version roll back, is it possible in safe way? Thanks again.

[sgiehl]

@L3on1d That depends which version you had used before. Switching between patch releases might be possible, but going back to a previous minor release could cause trouble, depending on the included changes. In general I would recommend not to do that.

How many visits do you have a day? I guess the purging job might send a query for each visit that needs to be removed...

[L3on1d]

@sgiehl at the moment we are tracking 2 sites one via js script and another via log import. Average visitors count per day ~ 4-5 millions.

[sgiehl]

Ok. That sounds like a bigger set of data that needs to be removed daily.

@tsteur do you maybe have some hints on how to improve the performance of removing log data?

[tsteur]

Maybe https://github.com/matomo-org/matomo/issues/20221 would help?

[sgiehl]

@tsteur It doesn't sound like it tries to remove data for a removed site. I guess we have customers on cloud where more actions/visits are removed when data is purged. Was just wondering if we had similar problems and maybe solved them somehow, or if this is more a problem of configuring and setting up mysql in a better way maybe...

[tsteur]

@sgiehl my understanding is that the same logic may be used for daily raw data deletion? Maybe that isn't the case?

[L3on1d]

In case someone needs solution - Uncheck "Regularly delete old raw data" in GUI control panel, create simple bash script to remove old logs via cli (./console core:delete-logs-data --dates=X,Y --idsite=X --no-interaction). Don't forget to defragment log tables (I use pt-online-schema-change tool from Percona), mysqltuner can show how much space you can reclaim.