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

Hi!

After updating to Matomo 3.12.0 to get the Goal fix, we are experiencing a slower processing time for the “core:archive” job. Before the update the CRON job took 30-40 minutes. At the moment the process takes between 1.5 and 5.5 hours.

Most of the core:archive process time is used in “Segments”. We have two sites (out of 33 sites) that have 24 and 38 segments. The other sites uses segments very little or not at all.

All plugins are updated, except:
AbTesting 3.2.14 => 3.2.15
CustomReports 3.1.19 => 3.1.20
Funnels 3.1.16 => 3.1.17

The OS, PHP, and MariaDB is running the same version as before the update. I’ve updated wait_timeout = 115200 in Mariadb to get rid of some “SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded”.

Matomo is running in a multi_server_environment.

Any ideas on next step? Do we need to remove/rebuild/redo segments?

At the moment I’m running a script controlling the archiving process, because of the variation in time consumption. I would like to go back to CRON controlled :slight_smile:

Thank you!
Best regards
Flemming

Did you also experience a significant increase of the archive tables sizes? Then you are probably affected by https://github.com/matomo-org/matomo/issues/10439


I am seeing some large tables. I’ll try to run the commands

./console core:purge-old-archive-data all
./console database:optimize-archive-tables all

Maybe it’ll help :slight_smile:

Archiving has taking 5-6 hours during the night

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