Segmented Visitor Log high CPU load #13329

kaplun · 2018-08-21T13:59:27Z

I am trying to generate "Segmented Visitor Log"s for milldy accessed URLs, say 300 visit today. The server fails to reply on time. I checked and, while the database seems barely used for the response, the corresponding PHP(-fpm) process that is tasked with the reply is taking up 100% CPU and is not able to reply in time (I guess with respect to the Ngnix timeout I have set up).

I checked with strace to see what the process is busy doing and to my surprise I have seen that is opening thousands of times the same files:

access("/var/www/html/piwik/tmp/assets", W_OK) = 0
access("/var/www/html/piwik/tmp/assets/asset_manager_global_css.css", R_OK) = 0
open("/var/www/html/piwik/tmp/assets/asset_manager_global_css.css", O_RDONLY) = 11
fstat(11, {st_mode=S_IFREG|0644, st_size=351893, ...}) = 0
lseek(11, 0, SEEK_CUR)                  = 0
fstat(11, {st_mode=S_IFREG|0644, st_size=351893, ...}) = 0
read(11, "/* compile_me_once=9c0304c15a2c4"..., 8192) = 8192
read(11, ": \"\\e62c\";\n}\n\n.icon-newtab:befor"..., 8192) = 8192
read(11, "1px}.ui-datepicker .ui-datepicke"..., 8192) = 8192
read(11, "lass_75_e6e6e6_1x400.png) 50% 50"..., 8192) = 8192
read(11, "ition:-96px -112px}.ui-icon-calc"..., 8192) = 8192
read(11, "background-color:#ec407a !import"..., 8192) = 8192
read(11, "mportant}.light-blue-text.text-a"..., 8192) = 8192
read(11, "xt.text-darken-2{color:#fbc02d !"..., 8192) = 8192
read(11, " !important}.grey-text.text-dark"..., 8192) = 8192
read(11, "ntent:\"\\00a0\"}table.responsive-t"..., 8192) = 8192
read(11, "66.6666666667%;margin-left:auto;"..., 8192) = 8192
[...]

This is repeated over and over again. I think there is some space for caching or moving this operation out of a loop.

I have tried enabling also the redis cache but the behavior is the same.

The text was updated successfully, but these errors were encountered:

tsteur · 2018-08-21T20:52:29Z

This is definitely supposed to be cached. Are you using any non-core plugins?

kaplun · 2018-08-22T07:41:16Z

Yes:

Official:
- CustomAlerts
- CustomDimensions
- InvalidateReports
- LogViewer
- MarketingCampaignsReporting
- SecurityInfo
- TasksTimetable
- TreemapVisualization
Third-party:
- AdminNotification
- ArchiveSite

kaplun · 2018-08-22T08:36:34Z

I tried to disable all of them, but the same behavior remained.

kaplun · 2018-09-06T09:55:42Z

Hi! This is becoming a blocker for us, because we can't use Matomo live to present data e.g. in meetings...

Is there any other information I can try to provide that might help to shed a light on this issue?

kaplun · 2018-09-06T12:06:00Z

For reference I took via strace a snapshot of the access syscall during some requests.

Note I am using PHP 7.2 with php-fpm:

The rows are sorted by number of occurrences of the syscall (first column). The second colum is the PID of the corresponding php-fpm process.

   6789 29118 access("/var/www/html/piwik/plugins/CoreHome/Tracker/VisitRequestProcessor.php", R_OK <unfinished ...>
   6792 22847 access("/var/www/html/piwik/plugins/Goals/Tracker/GoalsRequestProcessor.php", R_OK <unfinished ...>
   6831 22504 access("/var/www/html/piwik/plugins/MarketingCampaignsReporting/Tracker/RequestProcessor.php", R_OK <unfinished ...>
   6833 22504 access("/var/www/html/piwik/plugins/CustomVariables/Tracker/CustomVariablesRequestProcessor.php", R_OK <unfinished ...>
   6839 22504 access("/var/www/html/piwik/plugins/Ecommerce/Tracker/EcommerceRequestProcessor.php", R_OK <unfinished ...>
   6848 22504 access("/var/www/html/piwik/plugins/SitesManager/Tracker/SitesManagerRequestProcessor.php", R_OK <unfinished ...>
   6849 22847 access("/var/www/html/piwik/plugins/Actions/Tracker/ActionsRequestProcessor.php", R_OK <unfinished ...>
   6856 22504 access("/var/www/html/piwik/plugins/PrivacyManager/Tracker/RequestProcessor.php", R_OK <unfinished ...>
   6868 22504 access("/var/www/html/piwik/plugins/Heartbeat/Tracker/PingRequestProcessor.php", R_OK <unfinished ...>
   6869 22504 access("/var/www/html/piwik/plugins/Goals/Tracker/GoalsRequestProcessor.php", R_OK <unfinished ...>
   6872 22504 access("/var/www/html/piwik/plugins/CustomDimensions/Tracker/CustomDimensionsRequestProcessor.php", R_OK <unfinished ...>
   6885 22504 access("/var/www/html/piwik/plugins/Actions/Tracker/ActionsRequestProcessor.php", R_OK <unfinished ...>
   6885 22847 access("/var/www/html/piwik/plugins/CoreHome/Tracker/VisitRequestProcessor.php", R_OK <unfinished ...>
   7124 22507 access("/var/www/html/piwik/plugins/CustomDimensions/Tracker/CustomDimensionsRequestProcessor.php", R_OK <unfinished ...>
   7125 22507 access("/var/www/html/piwik/plugins/MarketingCampaignsReporting/Tracker/RequestProcessor.php", R_OK <unfinished ...>
   7194 22507 access("/var/www/html/piwik/plugins/PrivacyManager/Tracker/RequestProcessor.php", R_OK <unfinished ...>
   7200 22507 access("/var/www/html/piwik/plugins/Heartbeat/Tracker/PingRequestProcessor.php", R_OK <unfinished ...>
   7219 22507 access("/var/www/html/piwik/plugins/CustomVariables/Tracker/CustomVariablesRequestProcessor.php", R_OK <unfinished ...>
   7238 22507 access("/var/www/html/piwik/plugins/Goals/Tracker/GoalsRequestProcessor.php", R_OK <unfinished ...>
   7238 22507 access("/var/www/html/piwik/plugins/SitesManager/Tracker/SitesManagerRequestProcessor.php", R_OK <unfinished ...>
   7259 22507 access("/var/www/html/piwik/plugins/Ecommerce/Tracker/EcommerceRequestProcessor.php", R_OK <unfinished ...>
   7350 22507 access("/var/www/html/piwik/plugins/CoreHome/Tracker/VisitRequestProcessor.php", R_OK <unfinished ...>
   7379 22507 access("/var/www/html/piwik/plugins/Actions/Tracker/ActionsRequestProcessor.php", R_OK <unfinished ...>
  19887 22846 access("/var/www/html/piwik/tmp/assets/asset_manager_global_css.css", R_OK <unfinished ...>
  19959 22846 access("/var/www/html/piwik/tmp/assets", W_OK <unfinished ...>

See how the PID 22846 opened 19887 times /var/www/html/piwik/tmp/assets/asset_manager_global_css.css and 199959 /var/www/html/piwik/tmp/assets (this was one request!).

The other processes where busy performing bulk tracking (see how the same .php files are opened several times).

kaplun · 2018-09-06T12:07:45Z

Could it be there is some flag I am missing?

kaplun · 2018-09-06T12:10:50Z

BTW I am using:

[ChainedCache]
backends[] = "array"
backends[] = "redis"
backends[] = "file"

So redis should actually contain the cached assets?

kaplun · 2018-09-06T12:28:59Z

Seems like https://github.com/matomo-org/matomo/blob/3.x-dev/core/AssetManager/UIAssetMerger.php#L148 (i.e. isFileUpToDate() which is quite heavy!) is called thousands times, instead of only once per request.

kaplun · 2018-09-06T12:46:20Z

Ha! If by hand I set:
https://github.com/matomo-org/matomo/blob/3.x-dev/core/View.php#L122

private $enableCacheBuster = false;

It works like a charme!

kaplun · 2018-09-06T13:00:54Z

@tsteur , @mattab what I found is only a workaround to temporary solve my specific issue, but it underlines there is something not wrong with the caching.

kaplun · 2018-09-06T13:08:48Z

And now the next thing that is happening is that the corresponding strace is filled up with thousands of SELECT * FROM matomo_user WHERE login = 'admin' i.e. calls to Model::getUser(), possibly one per each entry of the visitor log.

This is definitively something that could be cached :-) (Maybe to be addressed in a separate issue).

kaplun · 2018-09-20T07:51:50Z

Just bumping up this issue because it's really a bottle neck for high-traffic websites.

tsteur · 2018-09-20T20:48:24Z

We're not experiencing any such issues here AFAIK.
Maybe it helps disabling some plugins (eg the non-official ones) and seeing if problems still occur. Then disable the redis cache and see if problems still occur.

Also is this used in a load balanced environment? Looking at the code I wouldn't be surprised if redis causes this issue in a load balanced environment as maybe some paths that are different per server are stored in redis cache... cc @mattab fyi... we likely need to deprecate the redis cache adapter unless someone used a different redis config per server...

tsteur · 2018-09-20T20:49:01Z

If I had to guess, in case you are on a load balanced environment, the redis adapter may cause trouble. That's just a very rough guess though.

mattab · 2018-09-20T22:32:42Z

Please try disable Redis cache and try again? @kaplun

kaplun · 2018-09-21T15:09:29Z

I can try disabling redis, though I am not on a load balanced environment.

kaplun · 2018-09-21T15:14:06Z

I confirm say behavior. A storm of re-reading the asset_manager_global_css.css. (note that if I manually switch off the flag as mentioned in #13329 (comment) then no reprocessing happens, and everything is as fast as it should

tsteur · 2018-09-28T02:34:06Z

can you maybe add a debug_print_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); at the beginning of this function? https://github.com/matomo-org/matomo/blob/3.6.0/core/View.php#L327

It might be printing couple of times something... I'm kind of thinking maybe it goes in the rendering of the view too many times for you for some reason... like eg when visitor log is being viewed it does it too often etc.

tsteur · 2018-10-04T21:21:11Z

Also seeing how often this code https://github.com/matomo-org/matomo/blob/3.6.1-b2/core/View.php#L329-L338 might be executed during visitor log etc it might be actually good to cache the tagJsBuster and tagCss property in the StaticCache.

refs #13329 Might not fix #13329 but should improve performance when rendering multiple views per pageload. It can be eg many when viewing visitor log etc. As the issue is referring to the "Segmented Visitor Log", it could actually fix that issue. Maybe for some reason the file cannot be written and it always re-generates it. `piwikVersionBasedCacheBuster ` is already cached in the method itself.

tsteur · 2018-10-04T21:28:49Z

Created a PR https://github.com/matomo-org/matomo/pull/13536/files

@kaplun can you test this?

kaplun · 2018-10-05T08:34:03Z

Yes, sorry, I haven't time to try the debug_print_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS); but I will try your patch now.

kaplun · 2018-10-05T08:39:24Z

Yay. It seems to fix the problem!

refs #13329 Might not fix #13329 but should improve performance when rendering multiple views per pageload. It can be eg many when viewing visitor log etc. As the issue is referring to the "Segmented Visitor Log", it could actually fix that issue. Maybe for some reason the file cannot be written and it always re-generates it. `piwikVersionBasedCacheBuster ` is already cached in the method itself.

mattab added this to the 3.7.0 milestone Sep 20, 2018

mattab added the c: Performance For when we could improve the performance / speed of Matomo. label Sep 20, 2018

tsteur mentioned this issue Oct 4, 2018

Cache cacheBuster generation when rendering a view #13536

Merged

tsteur self-assigned this Oct 8, 2018

sgiehl closed this as completed in ccd3dc8 Nov 25, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Segmented Visitor Log high CPU load #13329

Segmented Visitor Log high CPU load #13329

kaplun commented Aug 21, 2018 •

edited

tsteur commented Aug 21, 2018

kaplun commented Aug 22, 2018

kaplun commented Aug 22, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 20, 2018

tsteur commented Sep 20, 2018

tsteur commented Sep 20, 2018

mattab commented Sep 20, 2018

kaplun commented Sep 21, 2018

kaplun commented Sep 21, 2018

tsteur commented Sep 28, 2018

tsteur commented Oct 4, 2018

tsteur commented Oct 4, 2018

kaplun commented Oct 5, 2018

kaplun commented Oct 5, 2018

Segmented Visitor Log high CPU load #13329

Segmented Visitor Log high CPU load #13329

Comments

kaplun commented Aug 21, 2018 • edited

tsteur commented Aug 21, 2018

kaplun commented Aug 22, 2018

kaplun commented Aug 22, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 6, 2018

kaplun commented Sep 20, 2018

tsteur commented Sep 20, 2018

tsteur commented Sep 20, 2018

mattab commented Sep 20, 2018

kaplun commented Sep 21, 2018

kaplun commented Sep 21, 2018

tsteur commented Sep 28, 2018

tsteur commented Oct 4, 2018

tsteur commented Oct 4, 2018

kaplun commented Oct 5, 2018

kaplun commented Oct 5, 2018

kaplun commented Aug 21, 2018 •

edited