CPU load (MySQL) and memory usage (PHP/FPM) suddenly very high

soardiac · May 7, 2021, 6:54am

Hi all

We run our matomo on a 16 (virtual) core server, 32GB memory. Usually, the load is low. We have high peaks because some of our products are this way, but the server always handeled it well.

Until april 21. All of a sudden, CPU load (MySQL) and memory usage (PHP/FPM) suddenly were very high and stayed this way since then. Traffic didnt change, neither o I know of any configuration change. I tried many things (reboots, change PHP version, change cron timing, disable Tag Manager, etc…), but nothing helps.

Any ideas?

CPU load and PHP memory usage of teh last 30 days, it all started on april 21.

(sorry, ist german. “CPU-Auslastung” means “CPU load”, “Speicherauslastung” means “memory usage”)

[edit:]
I asked the provider, too (it’s a managed virtual server), they say they observe more MySQL requests

it doesn’t really explain the very high CPU load. Some more requests, but much higher CPU load looks like “more complex” requests or “something messed up and runs forever”… I am desperate

soardiac · May 9, 2021, 11:45am

[edited to be more precise]

ok, I have some php threads that are obviously repsonsible for this high load (because when I kill them, CPU and memory get back to normal). these php threads cause mysql to use lots of CPU, they don’t use high CPU themselves.

./console climulti:request -q --matomo-domain=xxxxxxxx --superuser module=API&method=CoreAdminHome.archiveReports&xxxxxxxxxxxxx&plugin=CustomReports

These threads start and then never end (I had them running for over 60 hours). Is there a known bug or something I can change? MAybe in the PlugIn? searching here and with google didnt’t really help me.

I could deactivate the plugin (custom reports), but we pay for that and some folks rely on it…

ok, I also tried this: Matomo is slow after creating a custom report, funnel or installing users flow FAQ - Analytics Platform - Matomo. I’ve set rearchive_reports_in_past_last_n_months = 1 for now.

restarted server and waiting for the customreport-php threads to start…

soardiac · May 9, 2021, 5:33pm

aaaand… nope, didn’t change a thing. still CustomReports-Threads causing mysql to go crazy.

i am out of ideas

peterbo · May 9, 2021, 5:46pm

How’s the status of your archive_invalidations table? (number of invalidations, invalidation names, etc.)

soardiac · May 10, 2021, 6:20am

Thank you for responding! Voilà:

These are all 27 rows in that table.

BTW:
I have innodb_buffer_pool_size at 4GB by now. (should be ok with 32GB server ram).

I am trying to set /tmpdir in mysql to /run ram disk, but I don’t have the priveliges to do ist. so this is still open.

however, it did run for more than 2 years without that kind of serve rload and changed April 21. These server side optimazations might help, but something is wrong.

peterbo · May 10, 2021, 9:49am

Can you see exactly in the archiver, which segment is being archived at the moment? In most cases, the archiver is not as slow for processes that don’t work with segments.
Can you post the whole (anonymized) archiver output here?

soardiac · May 10, 2021, 10:46am

I try to find this output… told cron to email me, can’t find it anywhere. Is there a default log file for this or do I have to tell the archiver to log its output?

peterbo · May 10, 2021, 11:00am

Yep → ./console core:archive > /path/to/logfile.log

soardiac · May 10, 2021, 12:05pm

ok, I changed my cron to actually log and then tested it. It did run and end successfully (parallel to the high load stuff still hanging around)

I then restarted the server for good and let it run with -vvv, so there are now 400 lines in the log from this one run.
sites 1 to 17 seemed to be ok (no custom reports there anyway), so heres the log for site 18:

heres the “header”:

INFO [2021-05-10 11:35:10] 20286  ---------------------------
INFO [2021-05-10 11:35:10] 20286  INIT
INFO [2021-05-10 11:35:10] 20286  Running Matomo 4.2.1 as Super User
INFO [2021-05-10 11:35:10] 20286  ---------------------------
INFO [2021-05-10 11:35:10] 20286  NOTES
INFO [2021-05-10 11:35:11] 20286  - Async process archiving supported, using CliMulti.
INFO [2021-05-10 11:35:11] 20286  - Reports for today will be processed at most every 3600 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2021-05-10 11:35:11] 20286  - Archiving was last executed without error 27 min 56s ago
INFO [2021-05-10 11:35:11] 20286  - The following websites do not use the tracker: 
INFO [2021-05-10 11:35:11] 20286  ---------------------------
INFO [2021-05-10 11:35:11] 20286  START
INFO [2021-05-10 11:35:11] 20286  Starting Matomo reports archiving...

You see, “last executed without error 27 min 56s ago” was the test run I did (mentioned above). After the restart this one run skipped sites 1 to 17 because the configured 3600s aren’t over.

But still, site 18 (the one with the custom reports) starts, doesn’t skip and then …stays like this.

INFO [2021-05-10 11:38:47] 20286  Start processing archives for site 18.
DEBUG [2021-05-10 11:38:47] 20286  Checking for queued invalidations...
INFO [2021-05-10 11:38:47] 20286    Will invalidate archived reports for today in site ID = 18's timezone (2021-05-10 00:00:00).
INFO [2021-05-10 11:38:48] 20286    Will invalidate archived reports for yesterday in site ID = 18's timezone (2021-05-09 00:00:00).
DEBUG [2021-05-10 11:38:48] 20286    Found usable archive for [idSite = 18, period = day 2021-05-09,2021-05-09, segment = , plugin = ], skipping invalidation.
DEBUG [2021-05-10 11:38:48] 20286  Done invalidating
DEBUG [2021-05-10 11:38:48] 20286  Found duplicate invalidated archive (same archive currently in progress), ignoring: [idinvalidation = 117126, idsite = 18, period = day(2021-05-10 - 2021-05-10), name = done, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  No usable archive exists (ts_archived of existing = 2021-05-10 08:08:40, now = 2021-05-10 11:38:48).
DEBUG [2021-05-10 11:38:48] 20286  Processing invalidation: [idinvalidation = 117072, idsite = 18, period = week(2021-05-10 - 2021-05-16), name = done, segment = ].
DEBUG [2021-05-10 11:38:48] 20286  Found duplicate invalidated archive (same archive currently in progress), ignoring: [idinvalidation = 117127, idsite = 18, period = month(2021-05-01 - 2021-05-31), name = done, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  No usable archive exists (ts_archived of existing = , now = 2021-05-10 11:38:48).
DEBUG [2021-05-10 11:38:48] 20286  Processing invalidation: [idinvalidation = 98999, idsite = 18, period = month(2021-02-01 - 2021-02-28), name = done.CustomReports, segment = ].
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 116262, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 106454, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 106043, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 105632, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 105221, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 104764, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 104353, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 98936, idsite = 18, period = year(2021-01-01 - 2021-12-31), name = done.CustomReports, segment = ]
DEBUG [2021-05-10 11:38:48] 20286  No usable archive exists (ts_archived of existing = , now = 2021-05-10 11:38:48).
DEBUG [2021-05-10 11:38:48] 20286  Processing invalidation: [idinvalidation = 107314, idsite = 18, period = year(2020-01-01 - 2020-12-31), name = done.CustomReports, segment = ].
DEBUG [2021-05-10 11:38:48] 20286  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=week&date=2021-05-10&format=json&trigger=archivephp
DEBUG [2021-05-10 11:38:48] 20286  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2021-02-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=5
DEBUG [2021-05-10 11:38:48] 20286  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=18&period=year&date=2020-01-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=10
DEBUG [2021-05-10 11:38:48] 20286  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=18&period=week&date=2021-05-10&format=json&trigger=archivephp&pid=8f14614046a184314ec17bde0927b0dbfa2da056988b8915dd97332024253dca0a89415aac76cea0ee9f1079c51bb24d15800&runid=20286' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/8f14614046a184314ec17bde0927b0dbfa2da056988b8915dd97332024253dca0a89415aac76cea0ee9f1079c51bb24d15800.output 2>&1 &
DEBUG [2021-05-10 11:38:48] 20286  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2021-02-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=5&pid=31c70bbb3e4840079ca205aeebe3fdfad3b9903d4fd5832789e4da282d4b0995a6fd73b62d2d708a887e2d63a7972664602b1&runid=20286' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/31c70bbb3e4840079ca205aeebe3fdfad3b9903d4fd5832789e4da282d4b0995a6fd73b62d2d708a887e2d63a7972664602b1.output 2>&1 &
DEBUG [2021-05-10 11:38:48] 20286  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=18&period=year&date=2020-01-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=10&pid=8be125f89cbcfd4d4e6755f45ec2c8b64ea1f1b219f6b1eaf9ac4342463e656f3350c93cbe906e6aeb88d296ede885c0bd062&runid=20286' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/8be125f89cbcfd4d4e6755f45ec2c8b64ea1f1b219f6b1eaf9ac4342463e656f3350c93cbe906e6aeb88d296ede885c0bd062.output 2>&1 &

CPU load is a bit better than before because of some performance twaeking I guess, but still way higher than it was. It all starts with those last few lines in the log.

peterbo · May 10, 2021, 12:21pm

When did you update to 4.2.1 and when did you do the switch to PHP 8? Does this correlate with the higher cpu load in any way?

soardiac · May 10, 2021, 12:24pm

and one more: the next normally scheduled archive run (via cron) looks like this:

INFO [2021-05-10 12:05:01] 11766  ---------------------------
INFO [2021-05-10 12:05:01] 11766  INIT
INFO [2021-05-10 12:05:01] 11766  Running Matomo 4.2.1 as Super User
INFO [2021-05-10 12:05:01] 11766  ---------------------------
INFO [2021-05-10 12:05:01] 11766  NOTES
INFO [2021-05-10 12:05:01] 11766  - Async process archiving supported, using CliMulti.
INFO [2021-05-10 12:05:01] 11766  - Reports for today will be processed at most every 3600 seconds. You can change this value in Matomo UI > Settings > General Settings.
INFO [2021-05-10 12:05:01] 11766  - Archiving was last executed without error 57 min 46s ago
INFO [2021-05-10 12:05:01] 11766  - The following websites do not use the tracker: 
INFO [2021-05-10 12:05:01] 11766  - Continuing ongoing archiving run by pulling from shared idSite queue.
INFO [2021-05-10 12:05:01] 11766  ---------------------------
INFO [2021-05-10 12:05:01] 11766  START
INFO [2021-05-10 12:05:01] 11766  Starting Matomo reports archiving...
DEBUG [2021-05-10 12:05:01] 11766  Applying queued rearchiving...
INFO [2021-05-10 12:05:02] 11766  Start processing archives for site 19.
DEBUG [2021-05-10 12:05:02] 11766  Checking for queued invalidations...
INFO [2021-05-10 12:05:02] 11766    Will invalidate archived reports for today in site ID = 19's timezone (2021-05-10 00:00:00).
DEBUG [2021-05-10 12:05:02] 11766    Yesterday archive can be skipped due to no visits for idSite = 19, skipping invalidation...
DEBUG [2021-05-10 12:05:02] 11766  Done invalidating
DEBUG [2021-05-10 12:05:02] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:03:57, now = 2021-05-10 12:05:02).
DEBUG [2021-05-10 12:05:02] 11766  Processing invalidation: [idinvalidation = 117129, idsite = 19, period = day(2021-05-10 - 2021-05-10), name = done, segment = ].
DEBUG [2021-05-10 12:05:02] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117130, idsite = 19, period = week(2021-05-10 - 2021-05-16), name = done, segment = ]
DEBUG [2021-05-10 12:05:02] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117131, idsite = 19, period = month(2021-05-01 - 2021-05-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:02] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117132, idsite = 19, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:02] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:02] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=19&period=day&date=2021-05-10&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:02] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=19&period=day&date=2021-05-10&format=json&trigger=archivephp&pid=1f1391c3b96594bc3072bb99334e56da88c3a243176d686da7325033d3bd46abd84e18685bbe83e4ce08533dd014b2c307230&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/1f1391c3b96594bc3072bb99334e56da88c3a243176d686da7325033d3bd46abd84e18685bbe83e4ce08533dd014b2c307230.output 2>&1 &
INFO [2021-05-10 12:05:03] 11766  Archived website id 19, period = day, date = 2021-05-10, segment = '', 2 visits found. Time elapsed: 1.180s
DEBUG [2021-05-10 12:05:03] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:03:58, now = 2021-05-10 12:05:03).
DEBUG [2021-05-10 12:05:03] 11766  Processing invalidation: [idinvalidation = 117130, idsite = 19, period = week(2021-05-10 - 2021-05-16), name = done, segment = ].
DEBUG [2021-05-10 12:05:03] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117131, idsite = 19, period = month(2021-05-01 - 2021-05-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:03] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117132, idsite = 19, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:03] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:03] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=19&period=week&date=2021-05-10&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:03] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=19&period=week&date=2021-05-10&format=json&trigger=archivephp&pid=b59440d22e9370b489757d1bd2172e3b8006cd0d625e8e2f4c556258003d9202d7051c534885ab140fed9618230117fd84a10&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/b59440d22e9370b489757d1bd2172e3b8006cd0d625e8e2f4c556258003d9202d7051c534885ab140fed9618230117fd84a10.output 2>&1 &
INFO [2021-05-10 12:05:04] 11766  Archived website id 19, period = week, date = 2021-05-10, segment = '', 2 visits found. Time elapsed: 1.179s
DEBUG [2021-05-10 12:05:05] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:04:00, now = 2021-05-10 12:05:05).
DEBUG [2021-05-10 12:05:05] 11766  Processing invalidation: [idinvalidation = 117131, idsite = 19, period = month(2021-05-01 - 2021-05-31), name = done, segment = ].
DEBUG [2021-05-10 12:05:05] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117132, idsite = 19, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:05] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:05] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=19&period=month&date=2021-05-01&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:05] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=19&period=month&date=2021-05-01&format=json&trigger=archivephp&pid=addabd30e4946dae801a5e83b1177b61b04bcdc169e4c8abdf7324c7043648dbe46d22b8af53d3765eceae2d9481240a0b120&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/addabd30e4946dae801a5e83b1177b61b04bcdc169e4c8abdf7324c7043648dbe46d22b8af53d3765eceae2d9481240a0b120.output 2>&1 &
INFO [2021-05-10 12:05:06] 11766  Archived website id 19, period = month, date = 2021-05-01, segment = '', 22 visits found. Time elapsed: 1.178s
DEBUG [2021-05-10 12:05:06] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:04:01, now = 2021-05-10 12:05:06).
DEBUG [2021-05-10 12:05:06] 11766  Processing invalidation: [idinvalidation = 117132, idsite = 19, period = year(2021-01-01 - 2021-12-31), name = done, segment = ].
DEBUG [2021-05-10 12:05:06] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:06] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=19&period=year&date=2021-01-01&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:06] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=19&period=year&date=2021-01-01&format=json&trigger=archivephp&pid=d4d1e261fe42484f7105bf20b34fd5ffa0a7abc905d2b11625b51e4c7e9ff2982a468e640e3a90f21b98fcb021e1db126ece0&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/d4d1e261fe42484f7105bf20b34fd5ffa0a7abc905d2b11625b51e4c7e9ff2982a468e640e3a90f21b98fcb021e1db126ece0.output 2>&1 &
INFO [2021-05-10 12:05:07] 11766  Archived website id 19, period = year, date = 2021-01-01, segment = '', 102 visits found. Time elapsed: 1.178s
DEBUG [2021-05-10 12:05:07] 11766  No next invalidated archive.
INFO [2021-05-10 12:05:07] 11766  Finished archiving for site 19, 4 API requests, Time elapsed: 5.634s [1 / 2 done]
INFO [2021-05-10 12:05:07] 11766  Start processing archives for site 13.
DEBUG [2021-05-10 12:05:07] 11766  Checking for queued invalidations...
INFO [2021-05-10 12:05:07] 11766    Will invalidate archived reports for today in site ID = 13's timezone (2021-05-10 00:00:00).
DEBUG [2021-05-10 12:05:07] 11766    Found usable archive for [idSite = 13, period = day 2021-05-10,2021-05-10, segment = , plugin = ], skipping invalidation.
INFO [2021-05-10 12:05:07] 11766    Will invalidate archived reports for yesterday in site ID = 13's timezone (2021-05-09 00:00:00).
DEBUG [2021-05-10 12:05:07] 11766    Found usable archive for [idSite = 13, period = day 2021-05-09,2021-05-09, segment = , plugin = ], skipping invalidation.
DEBUG [2021-05-10 12:05:07] 11766  Done invalidating
DEBUG [2021-05-10 12:05:07] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:05:24, now = 2021-05-10 12:05:07).
DEBUG [2021-05-10 12:05:07] 11766  Processing invalidation: [idinvalidation = 117081, idsite = 13, period = day(2021-05-10 - 2021-05-10), name = done, segment = ].
DEBUG [2021-05-10 12:05:07] 11766  Could not find stored segment for done flag hash: donea5494dbe8f00307a29da3345196546ac
DEBUG [2021-05-10 12:05:07] 11766  Found invalidation for segment that does not have auto archiving enabled, skipping: 117091
DEBUG [2021-05-10 12:05:08] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117082, idsite = 13, period = week(2021-05-10 - 2021-05-16), name = done, segment = ]
DEBUG [2021-05-10 12:05:08] 11766  Could not find stored segment for done flag hash: donea5494dbe8f00307a29da3345196546ac
DEBUG [2021-05-10 12:05:08] 11766  Found invalidation for segment that does not have auto archiving enabled, skipping: 117092
DEBUG [2021-05-10 12:05:08] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117083, idsite = 13, period = month(2021-05-01 - 2021-05-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:08] 11766  Could not find stored segment for done flag hash: donea5494dbe8f00307a29da3345196546ac
DEBUG [2021-05-10 12:05:08] 11766  Found invalidation for segment that does not have auto archiving enabled, skipping: 117093
DEBUG [2021-05-10 12:05:08] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117086, idsite = 13, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:08] 11766  Could not find stored segment for done flag hash: donea5494dbe8f00307a29da3345196546ac
DEBUG [2021-05-10 12:05:08] 11766  Found invalidation for segment that does not have auto archiving enabled, skipping: 117096
DEBUG [2021-05-10 12:05:08] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:08] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=13&period=day&date=2021-05-10&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:08] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=13&period=day&date=2021-05-10&format=json&trigger=archivephp&pid=f508acf457b11b23d136f7eaabf8519706a936999e4aea42341626de369cc0ad186382b8a36483de719b75e6f505690707b80&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/f508acf457b11b23d136f7eaabf8519706a936999e4aea42341626de369cc0ad186382b8a36483de719b75e6f505690707b80.output 2>&1 &
INFO [2021-05-10 12:05:47] 11766  Archived website id 13, period = day, date = 2021-05-10, segment = '', 33298 visits found. Time elapsed: 39.336s
DEBUG [2021-05-10 12:05:47] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:06:50, now = 2021-05-10 12:05:47).
DEBUG [2021-05-10 12:05:47] 11766  Processing invalidation: [idinvalidation = 117082, idsite = 13, period = week(2021-05-10 - 2021-05-16), name = done, segment = ].
DEBUG [2021-05-10 12:05:47] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117083, idsite = 13, period = month(2021-05-01 - 2021-05-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:47] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117086, idsite = 13, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:47] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:47] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=13&period=week&date=2021-05-10&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:47] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=13&period=week&date=2021-05-10&format=json&trigger=archivephp&pid=011af789fae4b340ce115bef536f6b2b8105d448d21c6aa8185bba7e4d785f98596b02bad967d44cab9f1cc243bb963751ab0&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/011af789fae4b340ce115bef536f6b2b8105d448d21c6aa8185bba7e4d785f98596b02bad967d44cab9f1cc243bb963751ab0.output 2>&1 &
INFO [2021-05-10 12:05:49] 11766  Archived website id 13, period = week, date = 2021-05-10, segment = '', 33298 visits found. Time elapsed: 1.712s
DEBUG [2021-05-10 12:05:49] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:06:57, now = 2021-05-10 12:05:49).
DEBUG [2021-05-10 12:05:49] 11766  Processing invalidation: [idinvalidation = 117083, idsite = 13, period = month(2021-05-01 - 2021-05-31), name = done, segment = ].
DEBUG [2021-05-10 12:05:49] 11766  Found archive with intersecting period with others in concurrent batch, skipping until next batch: [idinvalidation = 117086, idsite = 13, period = year(2021-01-01 - 2021-12-31), name = done, segment = ]
DEBUG [2021-05-10 12:05:49] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:49] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=13&period=month&date=2021-05-01&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:49] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=13&period=month&date=2021-05-01&format=json&trigger=archivephp&pid=263bf36c0fbed453fd30b6c73a403643d6e0254b13555019ebfaed8866138d58088fcc7012eb8fe6e07136ed641fd834c08a0&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/263bf36c0fbed453fd30b6c73a403643d6e0254b13555019ebfaed8866138d58088fcc7012eb8fe6e07136ed641fd834c08a0.output 2>&1 &
INFO [2021-05-10 12:05:54] 11766  Archived website id 13, period = month, date = 2021-05-01, segment = '', 531027 visits found. Time elapsed: 5.186s
DEBUG [2021-05-10 12:05:54] 11766  No usable archive exists (ts_archived of existing = 2021-05-10 11:07:14, now = 2021-05-10 12:05:54).
DEBUG [2021-05-10 12:05:54] 11766  Processing invalidation: [idinvalidation = 117086, idsite = 13, period = year(2021-01-01 - 2021-12-31), name = done, segment = ].
DEBUG [2021-05-10 12:05:54] 11766  No next invalidated archive.
DEBUG [2021-05-10 12:05:54] 11766  Starting archiving for ?module=API&method=CoreAdminHome.archiveReports&idSite=13&period=year&date=2021-01-01&format=json&trigger=archivephp
DEBUG [2021-05-10 12:05:54] 11766  Running command: /opt/plesk/php/8.0/bin/php -q  /var/www/vhosts/xxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain='xxxxxxxxxxxx' --superuser 'module=API&method=CoreAdminHome.archiveReports&idSite=13&period=year&date=2021-01-01&format=json&trigger=archivephp&pid=226d3363bed9931159ccadbefed0fbefd008ec9ea0cd5b314275630c09870099833f582bad214603664700f25974790d684c0&runid=11766' > /var/www/vhosts/xxxxxxxxxxxx/httpdocs/tmp/climulti/226d3363bed9931159ccadbefed0fbefd008ec9ea0cd5b314275630c09870099833f582bad214603664700f25974790d684c0.output 2>&1 &
INFO [2021-05-10 12:06:12] 11766  Archived website id 13, period = year, date = 2021-01-01, segment = '', 8532672 visits found. Time elapsed: 18.103s
DEBUG [2021-05-10 12:06:12] 11766  No next invalidated archive.
INFO [2021-05-10 12:06:12] 11766  Finished archiving for site 13, 4 API requests, Time elapsed: 65.176s [2 / 2 done]
DEBUG [2021-05-10 12:06:13] 11766  No more sites left to archive, stopping.
INFO [2021-05-10 12:06:13] 11766  Done archiving!
INFO [2021-05-10 12:06:13] 11766  ---------------------------
INFO [2021-05-10 12:06:13] 11766  SUMMARY
INFO [2021-05-10 12:06:13] 11766  Processed 8 archives.
INFO [2021-05-10 12:06:13] 11766  Total API requests: 8
INFO [2021-05-10 12:06:13] 11766  done: 8 req, 71339 ms, no error
INFO [2021-05-10 12:06:13] 11766  Time elapsed: 71.339s
INFO [2021-05-10 12:06:13] 11766  ---------------------------
INFO [2021-05-10 12:06:13] 11766  SCHEDULED TASKS
DEBUG [2021-05-10 12:06:13] 11766  30 scheduled tasks loaded
INFO [2021-05-10 12:06:13] 11766  Starting Scheduled tasks... 
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 0:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 1:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 2:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 3:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 4:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 5:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 6:
DEBUG [2021-05-10 12:06:13] 11766  Task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker is scheduled to run again for 2021-05-10.
INFO [2021-05-10 12:06:13] 11766  Scheduler: executing task Piwik\Plugins\CustomJsTracker\Tasks.updateTracker...
INFO [2021-05-10 12:06:13] 11766  Scheduler: finished. Time elapsed: 0.007s
DEBUG [2021-05-10 12:06:13] 11766  Task Piwik\Plugins\TagManager\Tasks.regenerateReleasedContainers is scheduled to run again for 2021-05-10.
INFO [2021-05-10 12:06:13] 11766  Scheduler: executing task Piwik\Plugins\TagManager\Tasks.regenerateReleasedContainers...
INFO [2021-05-10 12:06:13] 11766  Scheduler: finished. Time elapsed: 0.271s
DEBUG [2021-05-10 12:06:13] 11766  Task Piwik\Plugins\AbTesting\Tasks.changeExperimentStatusIfNeeded is scheduled to run again for 2021-05-10.
INFO [2021-05-10 12:06:13] 11766  Scheduler: executing task Piwik\Plugins\AbTesting\Tasks.changeExperimentStatusIfNeeded...
INFO [2021-05-10 12:06:13] 11766  Scheduler: finished. Time elapsed: 0.001s
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 7:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 8:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 9:
DEBUG [2021-05-10 12:06:13] 11766  Task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData is scheduled to run again for 2021-05-10.
INFO [2021-05-10 12:06:13] 11766  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.deleteLogData...
INFO [2021-05-10 12:06:13] 11766  Scheduler: finished. Time elapsed: 0.002s
DEBUG [2021-05-10 12:06:13] 11766  Task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData is scheduled to run again for 2021-05-10.
INFO [2021-05-10 12:06:13] 11766  Scheduler: executing task Piwik\Plugins\PrivacyManager\Tasks.anonymizePastData...
INFO [2021-05-10 12:06:13] 11766  Scheduler: finished. Time elapsed: 0.002s
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 10:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 11:
DEBUG [2021-05-10 12:06:13] 11766  Executing tasks with priority 12:
INFO [2021-05-10 12:06:13] 11766  done
INFO [2021-05-10 12:06:13] 11766  ---------------------------

# ps aux | grep -i matomo shows me that the last of the site 18 commands (last line in the log of my previous post) is still running (and keeping CPU load high)

soardiac · May 10, 2021, 12:25pm

no, both were done way earlier, weeks. I did try with PHP 7.4, same result.

soardiac · May 10, 2021, 2:22pm

and now, 2 hours later, the next cronjob kicks in (it’s timed 5 */2 * * *. there was still one siteid=18 thread running, and now 3 more started

matomo_+  5665  1.5  0.4 519684 146404 ?       S    16:10   0:01 /opt/plesk/php/8.0/bin/php -q /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain=xxxxxxxxxxxxxx --superuser module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2021-04-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=6&pid=b1a2d24a2c3763e03b1416614db5981fd236fcc4ce3b5f96c29ad40d27111997a90285943a6c2d43958f0c3926a363187f100&runid=30856
matomo_+  5678  1.7  0.5 538976 165688 ?       S    16:10   0:01 /opt/plesk/php/8.0/bin/php -q /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain=xxxxxxxxxxxxxx --superuser module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2021-03-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=8&pid=115706c351255df95a04f92ae4b7b16d9895a95936555d0781d5344c8ed8c37cbea4e1acfc53f4dd8b850360b4f4e5d4db0a1&runid=30856
matomo_+  5691  2.0  0.5 555532 182300 ?       S    16:10   0:02 /opt/plesk/php/8.0/bin/php -q /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain=xxxxxxxxxxxxxx --superuser module=API&method=CoreAdminHome.archiveReports&idSite=18&period=month&date=2021-02-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=6&pid=781c90184b64f31d9d4c9195a4adbfe10992f819e795de67caff60cda9a7db95925ffb978ad54a1e81f248652bfdb379ff8d2&runid=30856
matomo_+ 30855  0.0  0.0 113284  1184 ?        Ss   16:05   0:00 /bin/bash -c /opt/php80/bin/php -d memory_limit=8192M /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console core:archive --url=https://xxxxxxxxxxxxxx -vvv > /var/www/vhosts/xxxxxxxxxxxxxx/logs/_archiver_log.log
matomo_+ 30856  1.0  0.1 315176 45648 ?        S    16:05   0:04 /opt/php80/bin/php -d memory_limit=8192M /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console core:archive --url=https://xxxxxxxxxxxxxx -vvv
matomo_+ 20280  0.0  0.0 138176 15296 ?        S    13:35   0:00 /usr/bin/python2 -Estt /usr/local/psa/admin/sbin/cron_task_executor -u matomo_admin -c /opt/php80/bin/php -d memory_limit=8192M /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console core:archive --url=https://xxxxxxxxxxxxxx -vvv > /var/www/vhosts/xxxxxxxxxxxxxx/logs/_archiver_log.log --env SHELL=/bin/bash
matomo_+ 20285  0.0  0.0 113284  1184 ?        S    13:35   0:00 /bin/bash -c /opt/php80/bin/php -d memory_limit=8192M /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console core:archive --url=https://xxxxxxxxxxxxxx -vvv > /var/www/vhosts/xxxxxxxxxxxxxx/logs/_archiver_log.log
matomo_+ 20286  0.0  0.1 315312 45696 ?        S    13:35   0:08 /opt/php80/bin/php -d memory_limit=8192M /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console core:archive --url=https://xxxxxxxxxxxxxx -vvv
matomo_+ 25369  6.0  0.5 544928 171716 ?       S    13:38   9:18 /opt/plesk/php/8.0/bin/php -q /var/www/vhosts/xxxxxxxxxxxxxx/httpdocs/console climulti:request -q --matomo-domain=xxxxxxxxxxxxxx --superuser module=API&method=CoreAdminHome.archiveReports&idSite=18&period=year&date=2020-01-01&format=json&plugin=CustomReports&trigger=archivephp&pluginOnly=1&requestedReport=10&pid=8be125f89cbcfd4d4e6755f45ec2c8b64ea1f1b219f6b1eaf9ac4342463e656f3350c93cbe906e6aeb88d296ede885c0bd062&runid=20286

(redacted output of # ps aux | grep -i matomo)

these are all siteid=18 threads that stay and push server load. site 18 is the only one that uses CustomReports (and it used HeatMaps, but i deactivated that plugin for testing). The rest runs through normally (according to the log)

EDIT:
Finally, I managed to have all CustomReports implementes as “Goals” and could then deactivate the plugin. and now no more zombie site 18 threads. just clean archiving as it sould be.

my conclusion for now: The Plugin CustomReports (v4.0.7) did somehow mess up on our server. There were just 6 simple CustomReports configured, that’s nothing the plugin shouldn’t be able to handle. So something is wrong with the plugin, the server or both.
but for now I think this is the solution for my server load problem. (even though it sucks to pay for a plugin we can’t use, of course.)
Should anyone have a idea about how to fix custom reports please post.