@kaplun opened this Issue on August 21st 2018

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.

@tsteur commented on August 21st 2018 Member

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

@kaplun commented on August 22nd 2018

Yes:

  • Official:
    • CustomAlerts
    • CustomDimensions
    • InvalidateReports
    • LogViewer
    • MarketingCampaignsReporting
    • SecurityInfo
    • TasksTimetable
    • TreemapVisualization
  • Third-party:
    • AdminNotification
    • ArchiveSite
@kaplun commented on August 22nd 2018

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

@kaplun commented on September 6th 2018

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 commented on September 6th 2018

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 commented on September 6th 2018

Could it be there is some flag I am missing?

@kaplun commented on September 6th 2018

BTW I am using:

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

So redis should actually contain the cached assets?

@kaplun commented on September 6th 2018

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 commented on September 6th 2018

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 commented on September 6th 2018

@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 commented on September 6th 2018

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 commented on September 20th 2018

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

@tsteur commented on September 20th 2018 Member

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 commented on September 20th 2018 Member

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 commented on September 20th 2018 Member

Please try disable Redis cache and try again? @kaplun

@kaplun commented on September 21st 2018

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

@kaplun commented on September 21st 2018

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 https://github.com/matomo-org/matomo/issues/13329#issuecomment-419079850 then no reprocessing happens, and everything is as fast as it should

@tsteur commented on September 28th 2018 Member

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 commented on October 4th 2018 Member

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.

@tsteur commented on October 4th 2018 Member
@kaplun commented on October 5th 2018

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

@kaplun commented on October 5th 2018

Yay. It seems to fix the problem!

Powered by GitHub Issue Mirror