Matomo log import very slow since update to Matomo 4

group-it · May 7, 2021, 10:12am

Hello,

We are using a cron job to upload log files from our Nginx reverse proxy to Matomo.

After we upgraded Matomo to version 4, the log import via the import_logs.py script is extremely slow and caused high CPU load on our database server. Before the update everything worked fine.

When running an import, only every 30 to 80 seconds records are written. The remaining time we only see 0 records/sec. Like here:

3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 2 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 274 lines recorded, 1 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 501 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)
3350 lines parsed, 775 lines recorded, 5 records/sec (avg), 0 records/sec (current)

We also tried to restore the database to a new server with MySQL Version 8.0.23, but there we could see the same behavior.

On a new, empty database the import of the logfiles works like a charm.

Here is the command we use to upload our log files:
sudo python3 /var/www/matomo/misc/log-analytics/import_logs.py --url=http://<site-URL> --add-sites-new-hosts --recorders=4 --force-lowercase-path <log file>
We also tried to use different values for recorders, also with no difference.

When monitoring the MySQL database we saw the following queries during the import which where slow and could cause the problem:

Info about the system:

MySQL:

Version: 5.7.26
CPU: 4Cores
MEM: 32GB
Table size:
– piwik_log_link_visit_action: ~5,8GB
– piwik_log_visit: ~150MB
– piwik_archive_blob_XXXX: ~80MB
– piwik_archive_numeric_XXXX: ~25MB

Matomo Server:

Matomo Version: 4.2.1
OS: Ubuntu 20.04.2 LTS
CPU: 2 Cores
MEM: 4GB
PHP: 7.4.3
Python: 3.8.5
Webserver: Apache/2.4.41
The System check shown no errors.

Log file:

Type: Nginx access log file
Size: ~330 MB, ~1000000 lines

Can someone please advise us on how to fix this problem?

Thank you

group-it · June 1, 2021, 8:18am

Hello,

we found a solution for the problem with slow performance during the import.

We updated the index ‘index_idsite_idvisitor’ of the table ‘piwik_log_visit’ with the following SQL statement:

ALTER TABLE `piwik_log_visit`
DROP INDEX `index_idsite_idvisitor` ,
ADD INDEX `index_idsite_idvisitor` (`idsite` ASC, `idvisitor` ASC, `visit_last_action_time` ASC);

This increased our import performance from 4-5 records/sec to ~450 records/sec.

The query_time for the select statement that caused the slow performance (see screenshot in the previous post) decreased from ~0,28 sec to ~0,0002 sec.

Trash_Mails · June 1, 2021, 10:28am

Hi,
Out of curiosity could please explain how you arrived to this particular statement? Did you try making changes to mysql conf etc?

group-it · June 2, 2021, 7:23am

Hi,
we used the slow query log to monitor what happens when Matomo imports data, and so we found the Query (the ‘select’ posted above), which slowed the process down.
With this knowledge, we tried out some changes to the MySQL conf but could not solve it this way.
So we started looking into the Query itself to optimize it.

Lukas · June 2, 2021, 7:46pm

Hi,

This might be related to

github.com/matomo-org/matomo

Matomo tracker select queries can get slow when most visits have same visitorId

opened 09:07PM - 07 Dec 20 UTC

closed 07:43PM - 06 Feb 23 UTC

tsteur

Major c: Performance

Say you are tracking apps and you send a userId with every tracking request. The…n by default the userId will be used to generate the visitorId. It may also be a problem if for every action a new visit is forced. Queries like this will become very slow: ```sql explain extended 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, campaign_content, campaign_group, campaign_id, campaign_keyword, campaign_medium, campaign_name, campaign_placement, campaign_source, last_idlink_va, custom_dimension_1, custom_dimension_2, custom_dimension_3, custom_dimension_4, custom_dimension_5, custom_dimension_6, 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 log_visit FORCE INDEX (index_idsite_idvisitor) WHERE idsite = '4' AND visit_last_action_time <= '2020-12-07 20:34:48' AND idvisitor = '...' ORDER BY visit_last_action_time DESC LIMIT 1 ``` Explain: ![image](https://user-images.githubusercontent.com/273120/101405243-ad1b4a80-393c-11eb-97ee-62df41a2cfa8.png) or ![image](https://user-images.githubusercontent.com/273120/109722670-df71d680-7c11-11eb-82ec-f35692e6ae3c.png) To workaround this performance issue set `[Tracker]enable_userid_overwrites_visitorid=0` in your `config/config.ini.php` if userId is used. If userId is not used, there is currently no workaround. Ideally we find a way to not needing this setting though. Maybe we could at least limit time range by adding to the where `visit_last_action_time > 1 year before upper limit `. It won't make it much better but at least it be slightly faster especially when the table has over the years collected many hundred thousands or millions of requests for the same visitor. In our use case we have for example for the same idVisitor 1.6M entries which is roughly 30% of all visits for the same visitor. We used to have this lower limit in the where clause but AFAIK we removed it for Cohorts. @diosmosis do you maybe remember? To make cohorts still useful, how far back would we need to look? 1 year? Or would it be fine to only look back 6 months? I suppose we'd need to look back kind of ideally at least 1 year for the reports to be fine when you look at months for cohorts. Any other thoughts on how to make this use case faster be appreciated **UPDATE** See my comment further below. This issue is now about changing the existing index according to https://matomo.org/faq/troubleshooting/how-do-i-improve-the-load-time-of-the-find-visitor-sql-query-when-visitors-have-many-visits/

This might help

To workaround this performance issue set [Tracker]enable_userid_overwrites_visitorid=0 in your config/config.ini.php if userId is used. If userId is not used, there is currently no workaround.