Archiving is very slow after update to Matomo 3.12.0 (Testing 1.13.0-b1)

After running the 2 commands, the database shrunk a bit.
The archiving time is still long. Last successful run was approx. 4 hours.
I’m running the archive job in a shell script to avoid running double CRON jobs :slight_smile:

The most time is used processing segments. It takes up 80-90 % of the time used.

Any hints is greatly appreciated :slight_smile:

Kind regards
Flemming

matomo_stat matomo_stat2

Hi @flaugaard did you apply this change before running the commands: Purge all older archives if newest is queryable. · matomo-org/matomo@3deb35f · GitHub ?

We just published 3.13.0-b1 which should fix the issue, could you try upgrade to latest beta with I would like to test early beta and RC releases, how do I enable automatic updates to use these development versions? FAQ - Analytics Platform - Matomo and let us know if the issue is fixed after 24 hours?

Thanks

Thank you! I’ll implement the package on test and preproduction now. Hopefully, I’ll have a go to production shortly.

The archive process has been between 4 hours and 45 minutes during the night.

I saw this error in the httpd log:
WARNING [2019-11-21 05:06:09] 30999 /var/www/html/piwik/libs/Zend/Db/Statement/Pdo.php(228): Warning - Packets out of order. Expected 1 received 0. Packet size=30 - Matomo 3.12.0 - Please report this message in the Matomo forums: https:/
/forum.matomo.org (please do a search first as it might have been reported already)

WARNING [2019-11-21 05:06:09] 30999 /var/www/html/piwik/libs/Zend/Db/Statement/Pdo.php(228): Warning - PDOStatement::execute(): MySQL server has gone away - Matomo 3.12.0 - Please report this message in the Matomo forums: https://forum.m
atomo.org (please do a search first as it might have been reported already)
WARNING [2019-11-21 05:06:09] 30999 /var/www/html/piwik/libs/Zend/Db/Statement/Pdo.php(228): Warning - PDOStatement::execute(): Error reading result set’s header - Matomo 3.12.0 - Please report this message in the Matomo forums: https://
forum.matomo.org (please do a search first as it might have been reported already)

Kind regards
Flemming

I have the b1 installed on production. The archive job is running.

I also added process_new_segments_from = “segment_last_edit_time” to the config, after reading about processing of segments here on forums.

Fingers crossed!

Kind regards
Flemming

Next run took 3:45 hours and gave two errors. Sorry about the log dump (from terminal :))

Kind regards
Flemming

Summary

INFO [2019-11-21 12:57:16] 12680 Error: Got invalid response from API request: ?module=API&method=API.get&idSite=5&period=month&date=2019-11-14,2019-11-30&format=php&segment=pageUrl%3D%5Eemu.dk%2525
2Fhf%25252Fkonferencer-og-moder%25252F&trigger=archivephp. Response was ‘a:2:{s:6:“result”;s:5:“error”;s:7:“message”;s:10120:"SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lo
ck; try restarting transaction #0 /var/www/html/piwik/libs/Zend/Db/Statement.php(300): Zend_Db_Statement_Pdo->_execute(Array) #1 /var/www/html/piwik/libs/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Stateme
nt->execute(Array) #2 /var/www/html/piwik/libs/Zend/Db/Adapter/Pdo/Abstract.php(238): Zend_Db_Adapter_Abstract->query(‘UPDATE matomo_a…’, Array) #3 /var/www/html/piwik/core/Db/Adapter/Pdo/Mysql.php(3
09): Zend_Db_Adapter_Pdo_Abstract->query(‘UPDATE matomo_a…’, Array) #4 /var/www/html/piwik/core/Db.php(276): Piwik\Db\Adapter\Pdo\Mysql->query(‘UPDATE matomo_a…’, Array) #5 /var/www/html/piwik/core
/DataAccess/Model.php(158): Piwik\Db::query(‘UPDATE matomo_a…’, Array) #6 /var/www/html/piwik/core/Archive/ArchiveInvalidator.php(371): Piwik\DataAccess\Model->updateArchiveAsInvalidated(‘matomo_archive
_…’, Array, Array, NULL) #7 /var/www/html/piwik/core/Archive/ArchiveInvalidator.php(210): Piwik\Archive\ArchiveInvalidator->markArchivesInvalidated(Array, Array, NULL) #8 /var/www/html/piwik/core/Archiv
e.php(508): Piwik\Archive\ArchiveInvalidator->markArchivesAsInvalidated(Array, Array, false) #9 /var/www/html/piwik/core/Archive.php(641): Piwik\Archive->invalidatedReportsIfNeeded() #10 /var/www/html/
piwik/core/Archive.php(620): Piwik\Archive->cacheArchiveIdsAfterLaunching(Array, Array) #11 /var/www/html/piwik/core/Archive.php(549): Piwik\Archive->getArchiveIds(Array) #12 /var/www/html/piwik/core/A
rchive.php(303): Piwik\Archive->get(Array, ‘numeric’) #13 /var/www/html/piwik/plugins/VisitsSummary/API.php(36): Piwik\Archive->getDataTableFromNumeric(Array) #14 [internal function]: Piwik\Plugins\Vis
itsSummary\API->get(‘5’, ‘month’, ‘2019-11-14,2019…’, ‘pageUrl%3D%5Eem…’, Array) #15 /var/www/html/piwik/core/API/Proxy.php(237): call_user_func_array(Array, Array) #16 /var/www/html/piwik/core/Contex
t.php(28): Piwik\API\Proxy->Piwik\API{closure}() #17 /var/www/html/piwik/core/API/Proxy.php(328): Piwik\Context::executeWithQueryParameters(Array, Object(Closure)) #18 /var/www/html/piwik/plugins/API/API
.php(435): Piwik\API\Proxy->call(’\Piwik\Plugins\…’, ‘get’, Array) #19 [internal function]: Piwik\Plugins\API\API->get(‘5’, ‘month’, ‘2019-11-14,2019…’, ‘pageUrl%3D%5Eem…’, Array) #20 /var/www
/html/piwik/core/API/Proxy.php(237): call_user_func_array(Array, Array) #21 /var/www/html/piwik/core/Context.php(28): Piwik\API\Proxy->Piwik\API{closure}() #22 /var/www/html/piwik/core/API/Proxy.php(328)
: Piwik\Context::executeWithQueryParameters(Array, Object(Closure)) #23 /var/www/html/piwik/core/API/Request.php(265): Piwik\API\Proxy->call(’\Piwik\Plugins\…’, ‘get’, Array) #24 /var/www/html/piwik/
plugins/API/Controller.php(41): Piwik\API\Request->process() #25 [internal function]: Piwik\Plugins\API\Controller->index() #26 /var/www/html/piwik/core/FrontController.php(589): call_user_func_array(A
rray, Array) #27 /var/www/html/piwik/core/FrontController.php(165): Piwik\FrontController->doDispatch(‘API’, false, Array) #28 /var/www/html/piwik/core/dispatch.php(34): Piwik\FrontController->dispatch
() #29 /var/www/html/piwik/index.php(27): require_once(’/var/www/html/p…’) #30 /var/www/html/piwik/core/CliMulti/RequestCommand.php(79): require_once(’/var/www/html/p…’) #31 /var/www/html/piwik/vendor/sy
mfony/console/Symfony/Component/Console/Command/Command.php(257): Piwik\CliMulti\RequestCommand->execute(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleO
utput)) #32 /var/www/html/piwik/vendor/symfony/console/Symfony/Component/Console/Application.php(874): Symfony\Component\Console\Command\Command->run(Object(Symfony\Component\Console\Input\ArgvInput), Obj
ect(Symfony\Component\Console\Output\ConsoleOutput)) #33 /var/www/html/piwik/vendor/symfony/console/Symfony/Component/Console/Application.php(195): Symfony\Component\Console\Application->doRunCommand(Obje
ct(Piwik\CliMulti\RequestCommand), Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput)) #34 [internal function]: Symfony\Component\Console\Application-&g
t;doRun(Object(Symfony\Component\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput)) #35 /var/www/html/piwik/core/Console.php(103): call_user_func(Array, Object(Symfony\Componen
t\Console\Input\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput)) #36 /var/www/html/piwik/core/Access.php(639): Piwik\Console->Piwik{closure}() #37 /var/www/html/piwik/core/Console.php(
104): Piwik\Access::doAsSuperUser(Object(Closure)) #38 /var/www/html/piwik/vendor/symfony/console/Symfony/Component/Console/Application.php(126): Piwik\Console->doRun(Object(Symfony\Component\Console\Inpu
t\ArgvInput), Object(Symfony\Component\Console\Output\ConsoleOutput)) #39 /var/www/html/piwik/console(27): Symfony\Component\Console\Application->run() #40 {main}, caused by: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction #0 /var/www/html/piwik/libs/Zend/Db/Statement/Pdo.php(228): PDOStatement->execute(Array) #1 /var/www/html/piwik/libs/Zend /Db/Statement.php(300): Zend_Db_Statement_Pdo->_execute(Array) #2 /var/www/html/piwik/libs/Zend/Db/Adapter/Abstract.php(479): Zend_Db_Statement->execute(Array) #3 /var/www/html/piwik/libs/Zend/Db/Adapter/Pdo/Abstract.php(238): Zend_Db_Adapter_Abstract->query(‘UPDATE matomo_a…’, Array) #4 /var/www/html/piwik/core/Db/Adapter/Pdo/Mysql.php(309): Zend_Db_Adapter_Pdo_Abstract->query('UPDATE matomo_a…
', Array) #5 /var/www/html/piwik/core/Db.php(2

INFO [2019-11-21 12:57:16] 12680 Error: Got invalid response from API request: ?module=API&method=API.get&idSite=14&period=month&date=2019-11-14,2019-11-30&format=php&segment=pageUrl%3D%5Euvm.dk%252
52Fgymnasiale-uddannelser%25252Fproever-og-eksamen%25252F&trigger=archivephp. Response was ‘a:2:{s:6:“result”;s:5:“error”;s:7:“message”;s:28968:"SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction - in plugin Goals #0 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(127): Piwik\ArchiveProcessor\PluginsArchiver->callAggregateAllPlugins(‘171’, ‘2’
, false) #1 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(77): Piwik\ArchiveProcessor\Loader->prepareAllPluginsArchive(‘171’, ‘2’) #2 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(63): Piwik\ArchiveProcessor\Loader->prepareArchiveImpl(‘VisitsSummary’) #3 /var/www/html/piwik/core/Context.php(75): Piwik\ArchiveProcessor\Loader->Piwik\ArchiveProcessor{closure}() #4 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(64): Piwik\Context::changeIdSite(14, Object(Closure)) #5 /var/www/html/piwik/core/Archive.php(867): Piwik\ArchiveProcessor\Loader->prepareArchive(‘VisitsSummary’) #6 /var/www/html/piwik/core/Archive.php(677): Piwik\Archive->prepareArchive(Array, Object(Piwik\Site), Object(Piwik\Period\Day)) #7 /var/www/html/piwik/core/Archive.php(620): Piwik\Archive->cacheArchiveIdsAfterLaunching(Array, Array) #8 /var/www/html/piwik/core/Archive.php(549): Piwik\Archive->getArchiveIds(Array) #9 /var/www/html/piwik/core/Archive.php(303): Piwik\Archive->get(Array, ‘numeric’) #10 /var/www/htm
l/piwik/core/ArchiveProcessor.php(571): Piwik\Archive->getDataTableFromNumeric(Array) #11 /var/www/html/piwik/core/ArchiveProcessor.php(258): Piwik\ArchiveProcessor->getAggregatedNumericMetrics(Array,
false) #12 /var/www/html/piwik/core/ArchiveProcessor/PluginsArchiver.php(305): Piwik\ArchiveProcessor->aggregateNumericMetrics(Array) #13 /var/www/html/piwik/core/ArchiveProcessor/PluginsArchiver.php(108)
: Piwik\ArchiveProcessor\PluginsArchiver->aggregateMultipleVisitsMetrics() #14 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(121): Piwik\ArchiveProcessor\PluginsArchiver->callAggregateCoreMetric
s() #15 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(77): Piwik\ArchiveProcessor\Loader->prepareAllPluginsArchive(false, false) #16 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(63): Piwik
ArchiveProcessor\Loader->prepareArchiveImpl(‘VisitsSummary’) #17 /var/www/html/piwik/core/Context.php(75): Piwik\ArchiveProcessor\Loader->Piwik\ArchiveProcessor{closure}() #18 /var/www/html/piwik/core
/ArchiveProcessor/Loader.php(64): Piwik\Context::changeIdSite(14, Object(Closure)) #19 /var/www/html/piwik/core/Archive.php(867): Piwik\ArchiveProcessor\Loader->prepareArchive(‘VisitsSummary’) #20 /var/ww
w/html/piwik/core/Archive.php(677): Piwik\Archive->prepareArchive(Array, Object(Piwik\Site), Object(Piwik\Period\Week)) #21 /var/www/html/piwik/core/Archive.php(620): Piwik\Archive->cacheArchiveIdsAfte
rLaunching(Array, Array) #22 /var/www/html/piwik/core/Archive.php(549): Piwik\Archive->getArchiveIds(Array) #23 /var/www/html/piwik/core/Archive.php(303): Piwik\Archive->get(Array, ‘numeric’) #24 /var/
www/html/piwik/core/ArchiveProcessor.php(571): Piwik\Archive->getDataTableFromNumeric(Array) #25 /var/www/html/piwik/core/ArchiveProcessor.php(258): Piwik\ArchiveProcessor->getAggregatedNumericMetrics(
Array, false) #26 /var/www/html/piwik/core/ArchiveProcessor/PluginsArchiver.php(305): Piwik\ArchiveProcessor->aggregateNumericMetrics(Array) #27 /var/www/html/piwik/core/ArchiveProcessor/PluginsArchiver.p
hp(108): Piwik\ArchiveProcessor\PluginsArchiver->aggregateMultipleVisitsMetrics() #28 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(121): Piwik\ArchiveProcessor\PluginsArchiver->callAggregateCor
eMetrics() #29 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(77): Piwik\ArchiveProcessor\Loader->prepareAllPluginsArchive(false, false) #30 /var/www/html/piwik/core/ArchiveProcessor/Loader.php(63):
Piwik\ArchiveProcessor\Loader->prepareArchiveImpl(‘VisitsSummary’) #31 /var/www/html/piwik/core/Context.php(75): Piwik\ArchiveProcessor\Loader->Piwik\ArchiveProcessor{closure}() #32 /var/www/html/piw
ik/core/ArchiveProcessor/Loader.php(64): Piwik\Context::changeIdSite(14, Object(Closure)) #33 /var/www/html/piwik/core/Archive.php(867): Piwik\ArchiveProcessor\Loader->prepareArchive(‘VisitsSummary’) #34
/var/www/html/piwik/core/Archive.php(677): Piwik\Archive->prepareArchive(Array, Object(Piwik\Site), Object(Piwik\Period\Month)) #35 /var/www/html/piwik/core/Archive.php(620): Piwik\Archive->cacheArchiv
eIdsAfterLaunching(Array, Array) #36 /var/www/html/piwik/core/Archive.php(549): Piwik\Archive->getArchiveIds(Array) #37 /var/www/html/piwik/core/Archive.php(303): Piwik\Archive->get(Array, ‘numeric’) #
38 /var/www/html/piwik/plugins/VisitsSummary/API.php(36): Piwik\Archive->getDataTableFromNumeric(Array) #39 [internal function]: Piwik\Plugins\VisitsSummary\API->get(‘14’, ‘month’, ‘2019-11-14,2019…’
, ‘pageUrl%3D%5Euv…’, Array) #40 /var/www/html/piwik/core/API/Proxy.php(237): call_user_func_array(Array, Array) #41 /var/www/html/piwik/core/Context.php(28): Piwik\API\Proxy->Piwik\API{closure}() #42
/var/www/html/piwik/core/API/Proxy.php(328): Piwik\Context::executeWithQueryParameters(Array, Object(Closure)) #43 /var/www/html/piwik/plugins/API/API.php(435): Piwik\API\Proxy->call(’\Piwik\Plugins\…
.’, ‘get’, Array) #44 [internal function]: Piwik\Plugins\API\API->get(‘14’, ‘month’, ‘2019-11-14,2019…’, ‘pageUrl%3D%5Euv…’, Array) #45 /var/www/html/piwik/core/API/Proxy.php(237): call_user_func_array(Array, Array) #46 /var/www/html/piwik/core/Context.php(28): Piwik\API\Proxy->Piwik\API{closure}() #47 /var/www/html/piwik/core/API/Proxy.php(328): Piwik\Context::executeWithQueryParameters(Array, Objec
t(Closure)) #48 /var/www/html/piwik/core/API/R

The nights archiving has taken 3:45, 4:50, 7 and 2 hours.
It seems like the most time is spent managing segment data.

matomo-db_usage-20191122

I’m seeing a reduction in report data_size and index_size. Is it possible that the prolonged run time of the archive process is an expression of slowly cleaning up (little by little)?

Kind regards
Flemming

The archiving process is still long, 2:55 - 3:00 pr. run.

I’ve seen some PHP memory errors (php.ini: memory_limit = 1024M)
[INFO [2019-11-26 06:33:11] 23963 [Error: Got invalid response from API request: ?module=API&method=API.get&idSite=4&period=year&date=2019-11-20,2019-12-31&format=php&segment=exitPageUrl%21%3Djira&trigger=archivephp. Response was ‘PHP Fatal error: Allowed memory size of 1073741824 bytes exhausted (tried to allocate 483328 bytes) in /var/www/html/piwik/core/DataAccess/ArchiveWriter.php on line 152 a:2:{s:6:“result”;s:5:“error”;s:7:“message”;s:284:"Allowed memory size of 1073741824 bytes exhausted (tried to allocate 483328 bytes) on /var/www/html/piwik/core/DataAccess/ArchiveWriter.php(152) #0 /var/www/html/piwik/core/ArchiveProcessor/PluginsArchiver.php(171): [xxDELETEDxx]\Plugins\UsersFlow\Archiver->callAggregateMultipleReports() ";}’

Is rc1 release, the same as b1?

Kind regards
Flemming

The platform is updated to 3.13.0 I’ll run an archiving process to see the time consumption. Fingers crossed :smiley:

After updating to Matomo 3.12.0, suddenly the number of junk files excessively increased in my computer that made the internet speed slow down. I installed the IOLO system mechanic to clear the junk files. Now my computer is working well.

After the update to 3.13, the archiving process is generally still longer, than 3.11.
It went from always being less than an hour, to more than an hour and up to almost 3.

Has the archiving process time gone up in general? Or is this just my installation? :thinking:

Best regards
Flemming

Hello,
We faced similar problem on Matomo 3.13.1. The archiving process loads 1 database core to 100%, works many hours, does not load CPU and consumes lower than 100 MB memory after begining to archive segment. We have CustomDimensions (v3.1.9), Funnels (v3.1.19), MultiChannelConversionAttribution (v3.0.7), UsersFlow (v3.1.11) plugins deployed. The segments are based on a custom dimension. Matomo does not accept tracking and user requests during the archiving. log_visit now has 544 862 rows, log_link_visit_action has 6 436 197. Matomo 3.11 with another segments archived 14 500 000 rows in log_link_visit_action without such problems on this Database server.
Can we do something to speed up the archiving of the segments ?

The commands of archiving processes are like the following:

./console -vvv -n core:archive --concurrent-requests-per-website=1 --concurrent-archivers=1 --disable-scheduled-tasks '--php-cli-options=-d memory_limit=2500M' --force-periods=day --force-idsites=1 --force-date-range 2020-01-09,2020-01-09

Logs of archiving process looks like the following:

2020-01-17T06:55:00.6932951Z + time -v ./console -vvv -n core:archive --concurrent-requests-per-website=1 --concurrent-archivers=1 --disable-scheduled-tasks '--php-cli-options=-d memory_limit=2500M' --force-periods=day --force-idsites=1 --force-date-range 2020-01-09,2020-01-09                                                                                                                                              
2020-01-17T06:55:02.187595689Z INFO [2020-01-17 06:55:02] 10  ---------------------------                                                                                                                        
2020-01-17T06:55:02.187656786Z INFO [2020-01-17 06:55:02] 10  INIT                                                                                                                                               
2020-01-17T06:55:02.187670366Z INFO [2020-01-17 06:55:02] 10  Running Matomo 3.13.1 as Super User                                                                                                                │
2020-01-17T06:55:02.187743071Z INFO [2020-01-17 06:55:02] 10  ---------------------------                                                                                                                        2020-01-17T06:55:02.187864503Z INFO [2020-01-17 06:55:02] 10  NOTES                                                                                                                                              
2020-01-17T06:55:02.305696869Z INFO [2020-01-17 06:55:02] 10  - Async process archiving supported, using CliMulti.                                                                                               
2020-01-17T06:55:02.305729125Z INFO [2020-01-17 06:55:02] 10  - Reports for today will be processed at most every 1 seconds. You can change this value in Matomo UI > Settings > General Settings.               
2020-01-17T06:55:02.305742495Z INFO [2020-01-17 06:55:02] 10  - Reports for the current week/month/year will be requested at most every 3600 seconds.                                                            
2020-01-17T06:55:02.307042824Z INFO [2020-01-17 06:55:02] 10  - Archiving was last executed without error 162 days 20 hours ago                                                                                  
2020-01-17T06:55:02.31183431Z INFO [2020-01-17 06:55:02] 10  - Will only process the following periods: day (--force-periods)                                                                                    
2020-01-17T06:55:02.312614713Z INFO [2020-01-17 06:55:02] 10  - Will invalidate archived reports for 2020-01-16 for following websites ids: 2                                                                   
2020-01-17T06:55:02.355420079Z INFO [2020-01-17 06:55:02] 10  - Will process 1 websites (--force-idsites)                                                                                                        │
2020-01-17T06:55:02.378409563Z INFO [2020-01-17 06:55:02] 10  ---------------------------                                                                                                                        
2020-01-17T06:55:02.378438078Z INFO [2020-01-17 06:55:02] 10  START                                                                                                                                              
2020-01-17T06:55:02.378478112Z INFO [2020-01-17 06:55:02] 10  Starting Matomo reports archiving...                                                                                                               
2020-01-17T06:55:02.422456968Z INFO [2020-01-17 06:55:02] 10  0 out of 1 archivers running currently                                                                                                             
2020-01-17T06:55:02.45496149Z INFO [2020-01-17 06:55:02] 10  Will pre-process for website id = 1, period = day, date = 2020-01-09,2020-01-09                                                                     │
2020-01-17T06:55:02.455022376Z INFO [2020-01-17 06:55:02] 10  - pre-processing all visits                                                                                                                        
2020-01-17T06:55:02.49717573Z DEBUG [2020-01-17 06:55:02] 10  /usr/local/bin/php -q -d memory_limit=2500M /var/www/html/console climulti:request -q --matomo-domain='' --superuser 'module=API&method=API.get&idSite=1&period=day&date=2020-01-09,2020-01-09&format=php&trigger=archivephp&pid=91b8c5276b90a550d050748dae35757e6d882ddbb563b67a57fd8f8e565491b37af289c992767738e5cf140a4b6eacd6e1050&runid=10' > /var/www/html/tmp/climulti/91b8c5276b90a550d050748dae35757e6d882ddbb563b67a57fd8f8e565491b37af289c992767738e5cf140a4b6eacd6e1050.output 2>&1 &                                                                                      
2020-01-17T07:39:40.964722784Z DEBUG [2020-01-17 07:39:40] 10  Earliest created time of segment 'dimension13=^17.8.' w/ idSite = 1 is found to be 2020-01-16. Latest edit time is found to be 2020-01-16.        
2020-01-17T07:39:40.964837795Z DEBUG [2020-01-17 07:39:40] 10  process_new_segments_from set to beginning_of_time or cannot recognize value                                                                      
2020-01-17T07:39:41.006938083Z DEBUG [2020-01-17 07:39:41] 10  Earliest created time of segment 'dimension13=^18.0.' w/ idSite = 1 is found to be 2020-01-16. Latest edit time is found to be 2020-01-16.        
2020-01-17T07:39:41.00696993Z DEBUG [2020-01-17 07:39:41] 10  process_new_segments_from set to beginning_of_time or cannot recognize value                                                                       
2020-01-17T07:39:41.055210847Z DEBUG [2020-01-17 07:39:41] 10  Earliest created time of segment 'dimension13=^18.0.;dimension15==smb%252Fdatabase%252Flist' w/ idSite = 1 is found to be 2020-01-16. Latest edit 
time is found to be 2020-01-16.                                                                                                                                                                                   
2020-01-17T07:39:41.055274525Z DEBUG [2020-01-17 07:39:41] 10  process_new_segments_from set to beginning_of_time or cannot recognize value                                                                      │
2020-01-17T07:39:41.269250718Z DEBUG [2020-01-17 07:39:41] 10  General tracker cache was re-created.                                                                                                             
2020-01-17T07:39:41.290536523Z INFO [2020-01-17 07:39:41] 10  - pre-processing segment 1/3 dimension13=^17.8. [date = 2020-01-09,2020-01-09]                                                                     
2020-01-17T07:39:41.313685223Z DEBUG [2020-01-17 07:39:41] 10  /usr/local/bin/php -q -d memory_limit=2500M /var/www/html/console climulti:request -q --matomo-domain='' --superuser 'module=API&method=API.get&id
Site=1&period=day&date=2020-01-09,2020-01-09&format=php&segment=dimension13%3D%5E17.8.&trigger=archivephp&pid=a1de52b716f2b5be819d1a5434ad644674bdfb36d55135cef2791eb47a9b0899a68dac23c4e52f5ff534bed730594993084f0&runid=10' > /var/www/html/tmp/climulti/a1de52b716f2b5be819d1a5434ad644674bdfb36d55135cef2791eb47a9b0899a68dac23c4e52f5ff534bed730594993084f0.output 2>&1 &

“mysql -e ‘show full processlist\G;’” shows slow queries like the following:

*************************** 1. row ***************************
     Id: 18133
   User: matomo-test
   Host: n33:36386
     db: matomo-test
Command: Sleep
   Time: 7546
  State: 
   Info: NULL
*************************** 2. row ***************************
     Id: 18134
   User: matomo-test
   Host: n33:34692
     db: matomo-test
Command: Sleep
   Time: 8706
  State: 
   Info: NULL
*************************** 3. row ***************************
     Id: 18136
   User: matomo-test
   Host: n40:46926
     db: matomo-test
Command: Sleep
   Time: 9425
  State: 
   Info: NULL
*************************** 4. row ***************************
     Id: 18228
   User: matomo-test
   Host: n40:52236
     db: matomo-test
Command: Query
   Time: 9364
  State: Sending data
   Info: SELECT
				
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `eventCategory`
				END AS `eventCategory`
			, 
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `eventAction`
				END AS `eventAction`
			, 
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `eventName`
				END AS `eventName`
			
				, `1`, sum(`34`) AS `34`, sum(`2`) AS `2`, sum(`38`) AS `38`, sum(`35`) AS `35`, min(`36`) AS `36`, max(`37`) AS `37`
			FROM ( 
			SELECT
				`eventCategory`, `eventAction`, `eventName`,
				
			CASE
				WHEN @counter = 50001 THEN 50001
				ELSE @counter:=@counter+1
			END
		 AS counter
				, `1`, `34`, `2`, `38`, `35`, `36`, `37`
			FROM
				( SELECT @counter:=0 ) initCounter,
				( /* trigger = CronArchive */

			SELECT
				
                log_action_event_category.name as eventCategory,
                log_action_event_action.name as eventAction,
                log_action_event_name.name as eventName,

				count(distinct log_link_visit_action.idvisit) as `2`,
				count(distinct log_link_visit_action.idvisitor) as `1`,
				count(*) as `34`,

				sum(
					case when custom_float is null
						then 0
						else custom_float
					end
				) as `35`,
				sum( case when custom_float is null then 0 else 1 end )
				    as `38`,
				min(custom_float) as `36`,
				max(custom_float) as `37`
        
			FROM
				logtmpsegment540ac9654778034030a60d2c18c6bcc3 AS logtmpsegment540ac9654778034030a60d2c18c6bcc3 INNER JOIN log_link_visit_action AS log_link_visit_action ON log_link_visit_action.idvisit = logtmpsegment540ac9654778034030a60d2c18c6bcc3.idvisit LEFT JOIN log_action AS log_action_event_category ON log_link_visit_action.idaction_event_category = log_action_event_category.idaction LEFT JOIN log_action AS log_action_event_action ON log_link_visit_action.idaction_event_action = log_action_event_action.idaction LEFT JOIN log_action AS log_action_event_name ON log_link_visit_action.idaction_name = log_action_event_name.idaction
			WHERE
				log_link_visit_action.idaction_event_category IS NOT NULL
			GROUP BY
				log_link_visit_action.idaction_event_category,
                    log_link_visit_action.idaction_event_action,
                    log_link_visit_action.idaction_name
			ORDER BY
				`2` DESC, `eventName` ) actualQuery
		 ) AS withCounter
			GROUP BY counter
*************************** 5. row ***************************
     Id: 18307
   User: matomo-test
   Host: n33:49070
     db: matomo-test
Command: Sleep
   Time: 8704
  State: 
   Info: NULL
*************************** 6. row ***************************
     Id: 18308
   User: matomo-test
   Host: n33:49074
     db: matomo-test
Command: Query
   Time: 8688
  State: Sending data
   Info: SELECT
				
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `idaction`
				END AS `idaction`
			, 
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `name`
				END AS `name`
			
				, `url_prefix`, min(`28`) AS `28`, sum(`29`) AS `29`, sum(`2`) AS `2`, `1`, sum(`12`) AS `12`, sum(`30`) AS `30`, sum(`31`) AS `31`, min(`32`) AS `32`, max(`33`) AS `33`, `type`
			FROM ( 
			SELECT
				`idaction`, `name`,
				
			CASE
				WHEN `type` = 1 AND @counter1 = 50001 THEN 50001
				WHEN `type` = 1 THEN @counter1:=@counter1+1
				WHEN `type` = 2 AND @counter2 = 50001 THEN 50001
				WHEN `type` = 2 THEN @counter2:=@counter2+1
				WHEN `type` = 3 AND @counter3 = 50001 THEN 50001
				WHEN `type` = 3 THEN @counter3:=@counter3+1
				WHEN `type` = 4 AND @counter4 = 50001 THEN 50001
				WHEN `type` = 4 THEN @counter4:=@counter4+1
				ELSE 0
			END
		 AS counter
				, `url_prefix`, `28`, `29`, `2`, `1`, `12`, `30`, `31`, `32`, `33`, `type`
			FROM
				( SELECT @counter1:=0 ) initCounter1, ( SELECT @counter2:=0 ) initCounter2, ( SELECT @counter3:=0 ) initCounter3, ( SELECT @counter4:=0 ) initCounter4, 
				( /* trigger = CronArchive */

			SELECT
				log_action.name,
                log_action.type,
                log_action.idaction,
                log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(
                        case when custom_float is null
                            then 0
                            else custom_float
                        end
                ) / 1000 as `30`, sum(
                    case when custom_float is null
                        then 0
                        else 1
                    end
                ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`,
                CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0
                    AND log_link_visit_action.custom_var_k5 = '_pk_scount')
                THEN 1 ELSE 0 END
                    AS `28`,
                SUM( CASE WHEN log_action_name_ref.type = 8
                      THEN 1 ELSE 0 END)
                    AS `29`
			FROM
				logtmpsegment582e647d460e04e5984c7d9d29e7d67a AS logtmpsegment582e647d460e04e5984c7d9d29e7d67a INNER JOIN log_link_visit_action AS log_link_visit_action ON log_link_visit_action.idvisit = logtmpsegment582e647d460e04e5984c7d9d29e7d67a.idvisit LEFT JOIN log_action AS log_action ON log_link_visit_action.idaction_name = log_action.idaction LEFT JOIN log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idaction
			WHERE
				log_link_visit_action.idaction_name IS NOT NULL AND log_link_visit_action.idaction_event_category IS NULL AND (log_action.type IN (1, 2, 3, 4) OR log_action.type IS NULL)
			GROUP BY
				log_link_visit_action.idaction_name
			ORDER BY
				`12` DESC, name ASC ) actualQuery
		 ) AS withCounter
			GROUP BY counter, `type`
*************************** 7. row ***************************
     Id: 18431
   User: matomo-test
   Host: n33:32970
     db: matomo-test
Command: Sleep
   Time: 7546
  State: 
   Info: NULL
*************************** 8. row ***************************
     Id: 18432
   User: matomo-test
   Host: n33:32972
     db: matomo-test
Command: Query
   Time: 7528
  State: Sending data
   Info: SELECT
				
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `idaction`
				END AS `idaction`
			, 
				CASE
					WHEN counter = 50001 THEN '__mtm_ranking_query_others__'
					ELSE `name`
				END AS `name`
			
				, `url_prefix`, min(`28`) AS `28`, sum(`29`) AS `29`, sum(`2`) AS `2`, `1`, sum(`12`) AS `12`, sum(`30`) AS `30`, sum(`31`) AS `31`, min(`32`) AS `32`, max(`33`) AS `33`, `type`
			FROM ( 
			SELECT
				`idaction`, `name`,
				
			CASE
				WHEN `type` = 1 AND @counter1 = 50001 THEN 50001
				WHEN `type` = 1 THEN @counter1:=@counter1+1
				WHEN `type` = 2 AND @counter2 = 50001 THEN 50001
				WHEN `type` = 2 THEN @counter2:=@counter2+1
				WHEN `type` = 3 AND @counter3 = 50001 THEN 50001
				WHEN `type` = 3 THEN @counter3:=@counter3+1
				WHEN `type` = 4 AND @counter4 = 50001 THEN 50001
				WHEN `type` = 4 THEN @counter4:=@counter4+1
				ELSE 0
			END
		 AS counter
				, `url_prefix`, `28`, `29`, `2`, `1`, `12`, `30`, `31`, `32`, `33`, `type`
			FROM
				( SELECT @counter1:=0 ) initCounter1, ( SELECT @counter2:=0 ) initCounter2, ( SELECT @counter3:=0 ) initCounter3, ( SELECT @counter4:=0 ) initCounter4, 
				( /* trigger = CronArchive */

			SELECT
				log_action.name,
                log_action.type,
                log_action.idaction,
                log_action.url_prefix, count(distinct log_link_visit_action.idvisit) as `2`, count(distinct log_link_visit_action.idvisitor) as `1`, count(*) as `12`, sum(
                        case when custom_float is null
                            then 0
                            else custom_float
                        end
                ) / 1000 as `30`, sum(
                    case when custom_float is null
                        then 0
                        else 1
                    end
                ) as `31`, min(custom_float) / 1000 as `32`, max(custom_float) / 1000 as `33`,
                CASE WHEN (MAX(log_link_visit_action.custom_var_v5) = 0
                    AND log_link_visit_action.custom_var_k5 = '_pk_scount')
                THEN 1 ELSE 0 END
                    AS `28`,
                SUM( CASE WHEN log_action_name_ref.type = 8
                      THEN 1 ELSE 0 END)
                    AS `29`
			FROM
				logtmpsegment7db0fa0a71f6b22382eb37c8828ec125 AS logtmpsegment7db0fa0a71f6b22382eb37c8828ec125 INNER JOIN log_link_visit_action AS log_link_visit_action ON log_link_visit_action.idvisit = logtmpsegment7db0fa0a71f6b22382eb37c8828ec125.idvisit LEFT JOIN log_action AS log_action ON log_link_visit_action.idaction_name = log_action.idaction LEFT JOIN log_action AS log_action_name_ref ON log_link_visit_action.idaction_name_ref = log_action_name_ref.idaction
			WHERE
				log_link_visit_action.idaction_name IS NOT NULL AND log_link_visit_action.idaction_event_category IS NULL AND (log_action.type IN (1, 2, 3, 4) OR log_action.type IS NULL)
			GROUP BY
				log_link_visit_action.idaction_name
			ORDER BY
				`12` DESC, name ASC ) actualQuery
		 ) AS withCounter
			GROUP BY counter, `type`
*************************** 9. row ***************************
     Id: 19257
   User: root
   Host: localhost
     db: NULL
Command: Query
   Time: 0
  State: starting
   Info: show full processlist

Just upgraded to 3.13.1, I think from 13.11. We used to run archiving successfully hourly and have yet to complete archiving for our two largest site, though the smaller sites ran fine. I temporarily disabled cron archiving and am running archiving for just the second larges site, about 350K visits/day, from the command line. It’s been running for 10 hours, no errors yet, and totals are starting to fill in. I don’t see any obvious signs of CPU or DB overloads or bottlenecks.

skelley, do you have Matomo segments deployed in your Matomo instance?

We are now running Matomo 3.13.1, with CustomDimensions installed.
The archiving process is still time consuming, and is rarely under 2 hours.

yes, we use Matomo segments

We removed the custom segments defined on the two large volume sites and the archiving process is still taking days for these sites.

One thing that we have found will exponentially increase archiving time is bot activity combined with segments. If we have a bot hit a high traffic site that generates hundreds of pageviews for a visit (sometimes we see > 1,000 for the types of bots that hit our sites), for some reason the archive process will spike the cpus (2-3x normal) for at least a day or two for that site with segments (until the last2 period clears for the activity in the archive runs and the same time of bot behavior doesn’t recur).

What we do is identify the bot by searching for max actions >= the high number we see on a day’s overview report to find the partial IP, then filter that IP out going forward and will sometimes use the GDPR tools to search and remove that traffic. When we do, an archive run completes normally and within what we usually expect for cpu use. May not be related but though I’d share our experience.

2 Likes

Could be connected to this indexing issue: MariaDB | Slow Query | High CPU Load · Issue #15588 · matomo-org/matomo · GitHub