Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Wrong counting of concurrent archivers #13806

Closed
kaplun opened this issue Dec 5, 2018 · 15 comments · Fixed by #13821
Closed

Wrong counting of concurrent archivers #13806

kaplun opened this issue Dec 5, 2018 · 15 comments · Fixed by #13821
Labels
c: Website matomo.org For issues related to our matomo.org website.
Milestone
3.8.0

Comments

@kaplun
Copy link

kaplun commented Dec 5, 2018 •
edited

I have scheduled Matomo core:archive to run with --concurrent-archivers=5. I am understanding concurrent archivers are running via multiprocessing.

If I check in the log I see:

INFO [2018-12-05 14:19:11] 3066  ---------------------------
INFO [2018-12-05 14:19:11] 3066  START
INFO [2018-12-05 14:19:11] 3066  Starting Matomo reports archiving...
INFO [2018-12-05 14:19:11] 3066  3 out of 5 archivers running currently

However in the current running process I have:

root      3065  0.0  0.0 218572  3532 pts/2    S+   14:19   0:00 sudo -u nginx /var/www/html/piwik/console core:archive --concurrent-archivers=5
nginx     3066  0.0  0.0 353692 23284 pts/2    S+   14:19   0:02 php /var/www/html/piwik/console core:archive --concurrent-archivers=5
nginx     3166  0.0  0.6 478624 148156 pts/2   S+   14:19   0:02 /usr/bin/php -q /var/www/html/piwik/console climulti:request -q --matomo-domain= --superuser module=API&method=API.get&idSite=4&period=day&date=last52&format=php&trigger=archivephp&pid=REDACTED&runid=3066
root     18734  0.0  0.0 112728   968 pts/1    S+   15:03   0:00 grep --color=auto console

Isn't this just one archiver counted three times? (I know from the source code the counting is actually parsing the output of ps).

Also why aren't 2 more archivers also started?
@fdellwing
Copy link
Contributor

fdellwing commented Dec 5, 2018 •
edited

matomo/core/CliMulti/Process.php

Lines 243 to 250 in 0c72250

public static function getListOfRunningProcesses()
{
$processes = `ps ex 2>/dev/null`;
if (empty($processes)) {
return array();
}
return explode("\n", $processes);
}

matomo/core/CronArchive.php

Lines 388 to 412 in 0c72250

if ($this->maxConcurrentArchivers && $cliMulti->supportsAsync()) {
$numRunning = 0;
$processes = Process::getListOfRunningProcesses();
$instanceId = SettingsPiwik::getPiwikInstanceId();
foreach ($processes as $process) {
if (strpos($process, 'console core:archive') !== false &&
(!$instanceId
|| strpos($process, '--matomo-domain=' . $instanceId) !== false
|| strpos($process, '--matomo-domain="' . $instanceId . '"') !== false
|| strpos($process, '--matomo-domain=\'' . $instanceId . "'") !== false
|| strpos($process, '--piwik-domain=' . $instanceId) !== false
|| strpos($process, '--piwik-domain="' . $instanceId . '"') !== false
|| strpos($process, '--piwik-domain=\'' . $instanceId . "'") !== false)) {
$numRunning++;
}
}
if ($this->maxConcurrentArchivers < $numRunning) {
$this->logger->info(sprintf("Archiving will stop now because %s archivers are already running and max %s are supposed to run at once.", $numRunning, $this->maxConcurrentArchivers));
return;
} else {
$this->logger->info(sprintf("%s out of %s archivers running currently", $numRunning, $this->maxConcurrentArchivers));
}
}

After looking at the code, I don't know why it is counting 3. It would be very nice to have each $process printed. Could you add a $this->logger->info($process) to the foreach in your instance and post the output?

Also why aren't 2 more archivers also started?

The option sets the max used archivers, it could also use 1 of 100.

@tsteur
Copy link
Member

tsteur commented Dec 5, 2018

did you use ps ex 2 @kaplun ? If you know for each archive command you launch, there will be two entries, then I would simply double the limit... sometimes the same archive process might appear multiple times eg exec php ... might list 2 entries in PS in some environments etc.

@fdellwing
Copy link
Contributor

@tsteur Isn't the command simply ps ex? The 2>/dev/null part is only there to surpress errors, isn't it?

@tsteur
Copy link
Member

tsteur commented Dec 5, 2018

true 👍

@kaplun
Copy link
Author

kaplun commented Dec 5, 2018

The current log output is:

INFO [2018-12-05 21:38:41] 27687  24450 ?        S      9:42 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24451 ?        S      9:45 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24452 ?        S      9:52 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24481 ?        S      9:50 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24628 ?        S      9:49 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24672 ?        S      9:52 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  24682 ?        S      9:55 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  25163 ?        S      9:44 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  25766 ?        S      0:07 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  25785 ?        S      0:08 php-fpm: pool www
INFO [2018-12-05 21:38:41] 27687  27687 pts/3    S+     0:00 php /var/www/html/piwik/console core:archive --concurrent-archivers=5 HOSTNAME=REDACTED TERM=screen HISTSIZE=1000 LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36: USERNAME=root MAIL=/var/spool/mail/root LANG=it_CH.UTF-8 PATH=/sbin:/bin:/usr/sbin:/usr/bin LOGNAME=root USER=root HOME=/var/lib/nginx SHELL=/sbin/nologin SUDO_COMMAND=/var/www/html/piwik/console core:archive --concurrent-archivers=5 SUDO_USER=root SUDO_UID=0 SUDO_GID=0
INFO [2018-12-05 21:38:41] 27687  27757 pts/3    S+     0:00 sh -c ps ex 2>/dev/null HOSTNAME=REDACTED TERM=screen HISTSIZE=1000 LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36: USERNAME=root MAIL=/var/spool/mail/root LANG=it_CH.UTF-8 PATH=/sbin:/bin:/usr/sbin:/usr/bin LOGNAME=root USER=root HOME=/var/lib/nginx SHELL=/sbin/nologin SUDO_COMMAND=/var/www/html/piwik/console core:archive --concurrent-archivers=5 SUDO_USER=root SUDO_UID=0 SUDO_GID=0
INFO [2018-12-05 21:38:41] 27687  27758 pts/3    R+     0:00 ps ex HOSTNAME=REDACTED SHELL=/sbin/nologin TERM=screen HISTSIZE=1000 USER=root LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36: SUDO_USER=root SUDO_UID=0 USERNAME=root PATH=/sbin:/bin:/usr/sbin:/usr/bin MAIL=/var/spool/mail/root PWD=/root LANG=it_CH.UTF-8 SHLVL=1 SUDO_COMMAND=/var/www/html/piwik/console core:archive --concurrent-archivers=5 HOME=/var/lib/nginx LOGNAME=root SUDO_GID=0 _=/bin/ps
INFO [2018-12-05 21:38:41] 27687  31090 ?        Ss     0:00 /bin/sh -c /var/www/html/piwik/console core:archive --concurrent-archivers=5 2>&1 >> /var/log/matomo-archive.log XDG_SESSION_ID=24692 XDG_RUNTIME_DIR=/run/user/498 LANG=en_US.UTF-8 SHELL=/bin/sh HOME=/var/lib/nginx PATH=/usr/bin:/bin LOGNAME=nginx USER=nginx
INFO [2018-12-05 21:38:41] 27687  31091 ?        S      0:03 php /var/www/html/piwik/console core:archive --concurrent-archivers=5 XDG_SESSION_ID=24692 SHELL=/bin/sh USER=nginx PATH=/usr/bin:/bin PWD=/var/lib/nginx LANG=en_US.UTF-8 SHLVL=1 HOME=/var/lib/nginx LOGNAME=nginx XDG_RUNTIME_DIR=/run/user/498 _=/var/www/html/piwik/console
INFO [2018-12-05 21:38:41] 27687  31197 ?        S      6:11 /usr/bin/php -q /var/www/html/piwik/console climulti:request -q --matomo-domain= --superuser module=API&method=API.get&idSite=1&period=day&date=last52&format=php&trigger=archivephp&pid=REDACTED&runid=31091 XDG_SESSION_ID=24692 SHELL=/bin/sh USER=nginx PATH=/usr/bin:/bin _=/usr/bin/php PWD=/var/lib/nginxINFO [2018-12-05 21:38:41] 27687  31197 ?        S      6:11 /usr/bin/php -q /var/www/html/piwik/console climulti:request -q --matomo-domain= --superuser module=API&method=API.get&idSite=1&period=day&date=last52&format=php&trigger=archivephp&pid=REDACTED&runid=31091 XDG_SESSION_ID=24692 SHELL=/bin/sh USER=nginx PATH=/usr/bin:/bin _=/usr/bin/php PWD=/var/lib/nginx LANG=en_US.UTF-8 HOME=/var/lib/nginx SHLVL=2 LOGNAME=nginx XDG_RUNTIME_DIR=/run/user/498

@kaplun
Copy link
Author

kaplun commented Dec 5, 2018

A bit OT, for this issue, but is there a way to speed up the archiving by indeed having parallel requests for independent reports?

@kaplun
Copy link
Author

kaplun commented Dec 5, 2018

Ah and it says:

Archiving will stop now because 7 archivers are already running and max 5 are supposed to run at once.

@tsteur
Copy link
Member

tsteur commented Dec 6, 2018

It'll speed up if you have multiple sites, otherwise there isn't much of a benefit.

@kaplun
Copy link
Author

kaplun commented Dec 6, 2018

Oh. Is there a plan to parallelize e.g. to run different days in parallel and then recursively different weeks and so on?

@tsteur
Copy link
Member

tsteur commented Dec 6, 2018

no there are no plans. usually, you would run the archiver every day and it would only archive the current day anyway (from there the week etc)

@tsteur
Copy link
Member

tsteur commented Dec 10, 2018

@kaplun I think we can close the issue? We could possibly edit the FAQ though that sometimes you may need to double the amount of concurrent archivers if each archive process is listed twice. As far as I can tell it doesn't look like there's some bug otherwise.

@kaplun
Copy link
Author

kaplun commented Dec 10, 2018

Well, I think it's even counted 3 times, due to the wrong ps filtering. So maybe a smarter filter could be foreseen? Or using pid files?

But yeah otherwise it's not an high priority issue.

@tsteur
Copy link
Member

tsteur commented Dec 10, 2018

The logic is quite straight forward to count the number of processes. It simply lists each process ps ex and counts how many of those processes include console core:archive. We are using this feature also a lot and it works quite nicely. Is that randomly or always for you?

It might say 3 times because it includes the current core:archive process that is currently running and if you do afterwards ps ex, this process won't be shown anymore.

@kaplun
Copy link
Author

kaplun commented Dec 10, 2018

It's always due to the fact that I am using a cronjob with this format:

0 2 * * * nginx /var/www/html/piwik/console core:archive -vvv --concurrent-archivers=10 2>&1 >> /var/log/matomo-archive.log

So I guess there is one process for the sudo one for the sh and one for the actual script.

@tsteur
Copy link
Member

tsteur commented Dec 10, 2018

Sweet. I'll update the docs 👍

tsteur added a commit that referenced this issue Dec 10, 2018
@tsteur
Tweak description for concurrent-archivers
c12b920 
fix #13806
@tsteur tsteur mentioned this issue Dec 10, 2018
Merged
@tsteur tsteur added the c: Website matomo.org For issues related to our matomo.org website. label Dec 10, 2018
@tsteur tsteur added this to the 3.8.0 milestone Dec 10, 2018
diosmosis pushed a commit that referenced this issue Dec 11, 2018
@tsteur @diosmosis
Tweak description for concurrent-archivers (#13821)
ef5b071 
fix #13806
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
c: Website matomo.org For issues related to our matomo.org website.
Projects
None yet
Milestone
3.8.0
Development

Successfully merging a pull request may close this issue.

Tweak description for concurrent-archivers matomo-org/matomo
3 participants
@kaplun @tsteur @fdellwing