@toredash opened this Issue on May 6th 2019

Hi,

We see a high number of access() errors when tracing Matomo, and it is related to matomo trying to access() files which isn't present.

Since files are not present, opcache is unable to cache the code. There is a decent amount of files, here is a sample, I can provide a full list if needed. The number is the frequency seen in our stracing for 10s in our dev environment:

258 /var/www/bootstrap.php
247 /var/www/plugins/ExamplePluginTemplate
247 /var/www/config/config.php
244 /var/www/config/common.config.ini.php
243 /var/www/config/<matomo hostname>.config.ini.php
238 /var/www/misc/user/<matomo hostname>/config.ini.php
216 /var/www/plugins/Morpheus/Morpheus.php
215 /var/www/plugins/TasksTimetable/TasksTimetable.php
213 /var/www/plugins/CoreConsole/CoreConsole.php
160 /var/www/plugins/ExampleUI/ExampleUI.php
155 /var/www/plugins/ExampleSettingsPlugin/ExampleSettingsPlugin.php
155 /var/www/plugins/ExampleCommand/ExampleCommand.php
147 /var/www/config/environment/tracker.php
140 /var/www/plugins/CoreConsole/plugin.json
 60 /var/www/plugins/Proxy/config/config.php
 59 /var/www/plugins/SEO/config/config.php
 59 /var/www/plugins/CoreConsole/config/config.php
 36 /var/www/plugins/VisitorInterest/config/tracker.php
 36 /var/www/plugins/Feedback/config/tracker.php
 36 /var/www/plugins/DBStats/config/tracker.php
 36 /var/www/plugins/CoreUpdater/config/tracker.php
 35 /var/www/vendor/composer/../pear/pear-core-minimal/src/UsersManager/API.php
 35 /var/www/plugins/IntranetMeasurable/templates/
 35 /var/www/plugins/CustomReports/config/tracker.php
 35 /var/www/plugins/CustomDimensions/config/tracker.php
 35 /var/www/plugins/BulkTracking/templates/
 34 /var/www/vendor/composer/../pear/pear-core-minimal/src/AddSegmentBySegmentValue.php
 33 /var/www/plugins/UserId/templates/
33 /var/www/plugins/Proxy/templates/

When these files are not present, strace gives the following summary when stracing all php-fpm7 processes. Notice a lot of time is spent on access() calls:

% time     seconds  usecs/call     calls    errors syscall
------- ----------- ----------- --------- --------- ----------------
- 27.11    0.234576           5     47316     11338 access
- 13.30    0.115091           5     25394           clock_gettime
- 11.95    0.103429           5     19568       754 stat
-  9.85    0.085259           9      9602           getdents64
-  5.90    0.051080           7      7283           close
[...]

For a simple test, we added {config,tracker}.php to all plugins-folders where it was not present already, and returned an empty array:

cd /var/www/plugins
for dir in `ls`; do
  mkdir $dir/config
  [[ ! -f $dir/config/config.php ]] && echo "<?php return array(); ?>" > $dir/config/config.php
  [[ ! -f $dir/config/tracker ]] && echo "<?php return array(); ?>" > $dir/config/tracker.php
  chown -Rv nginx:nginx $dir/config
done

After adding this change, we restarted php-fpm7. Notice how much less time is spent with access() calls:

:% time     seconds  usecs/call     calls    errors syscall
------- ----------- ----------- --------- --------- ----------------
- 29.44    0.160735           5     32932      1484 stat
-  9.46    0.051630           4     12248           poll
-  9.25    0.050473           2     24130           clock_gettime
-  8.29    0.045251           5      9497      2725 access
-  7.30    0.039830           3     12064         4 recvfrom

For low level traffic, we don't see any improvements. But, when sudden peaks (16req/s to 1000req/s) occurs within 30s, we no longer have issues with increased latency on our Tracker API requests. Before this change, certain (5-10%) Tracking API calls would time out, since unneeded CPU time was spent on access() calls.

We have not fixed all identified "missing files", but if this is of interest I can provide some feedback on what other files might benefit from this. It is not enough to just touch files, e.g. Matomo expects an array() returned from {config,tracker}.php.

We haven't looked at increasing realpath-cache-ttl (https://www.php.net/manual/en/ini.core.php#ini.realpath-cache-ttl) but will look at it, but I suspect this will have less impact sin Opcache uses a shared cache.

I'm not sure what I expect Matomo devs to do with this, but it would be nice to avoid unnecessary access() syscalls in general. I suspect very few actually hit this issue at all, but still.

Our opcache settings:

opcache.enable=1
opcache.enable_cli=1
opcache.fast_shutdown=1
opcache.memory_consumption=64
opcache.interned_strings_buffer=16
opcache.validate_timestamps=false
opcache.enable_file_override=true
opcache.log_verbosity_level=2
opcache.file_update_protection=0

@tsteur commented on May 6th 2019 Member

That's a good find. I suppose PHP can cache these files. I suppose it be an easy fix to add the config/config/tracker.php files to all plugins returning an empty array. You'd need to look at the total result then though. Maybe it uses in the end more time when building the dependency injection container.

Those stats you show from how many requests is that? Maybe it's a very minor thing compared to the whole request? I reckon it can be helpful though to avoid the filesystem being a bottleneck when there's heaps of traffic.

I reckon I'd be keen to actually create those files for all of our core plugins.

@toredash commented on May 7th 2019

You'd need to look at the total result then though. Maybe it uses in the end more time when building the dependency injection container.

I don't understand what you mean by the "building the dependency injection container".

Those stats you show from how many requests is that? Maybe it's a very minor thing compared to the whole request? I reckon it can be helpful though to avoid the filesystem being a bottleneck when there's heaps of traffic.

I can create some stats for you if you need it. The best approach might be to benchmark a single php process, with and without the missing files present. It should provide with an estimate on how much more performance a single process would be able to gain. But for multiple processes I would assume the gain is bigger, since the kernel would have to do less work overall.

I reckon I'd be keen to actually create those files for all of our core plugins.

We have for now added the for loop described above to our entrypoint script container. Would love to see this upstream.

@toredash commented on May 21st 2019

We have implemented the change permanently now in our env. 'strace' now show much less time is spent on access syscalls:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 36.97    0.221039           3     74049       458 stat
 10.98    0.065627           3     20463       618 access
  9.62    0.057524           3     21818           read
  7.63    0.045614           2     21124           clock_gettime
  4.20    0.025128           3      8728           poll
  3.75    0.022423           5      4849           close
  3.17    0.018975           3      7528           rt_sigaction

There are still some files that isn't cached by opcache:

      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/AddSegmentBySegmentValue.php", F_OK) = -1 ENOENT (No such file or directory)
      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/ColumnCallbackDeleteMetadata.php", F_OK) = -1 ENOENT (No such file or directory)
      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/ColumnDelete.php", F_OK) = -1 ENOENT (No such file or directory)
      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/Limit.php", F_OK) = -1 ENOENT (No such file or directory)
      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/SafeDecodeLabel.php", F_OK) = -1 ENOENT (No such file or directory)
      1 /var/www/vendor/composer/../pear/pear-core-minimal/src/Sort.php", F_OK) = -1 ENOENT (No such file or directory)
      7 /var/www/vendor/composer/../pear/pear-core-minimal/src/UsersManager/API.php", F_OK) = -1 ENOENT (No such file or directory)
     18 /var/www/misc/user/10.32.9.150/config.ini.php", F_OK) = -1 ENOENT (No such file or directory)
     19 /var/www/config/10.32.9.150.config.ini.php", F_OK) = -1 ENOENT (No such file or directory)
     38 /var/www/plugins/ExampleSettingsPlugin/ExampleSettingsPlugin.php", F_OK) = -1 ENOENT (No such file or directory)
     39 /var/www/plugins/ExampleCommand/ExampleCommand.php", F_OK) = -1 ENOENT (No such file or directory)
     41 /var/www/plugins/ExampleUI/ExampleUI.php", F_OK) = -1 ENOENT (No such file or directory)
     74 /var/www/plugins/CoreConsole/CoreConsole.php", F_OK) = -1 ENOENT (No such file or directory)
     76 /var/www/plugins/TasksTimetable/TasksTimetable.php", F_OK) = -1 ENOENT (No such file or directory)
     77 /var/www/plugins/Morpheus/Morpheus.php", F_OK) = -1 ENOENT (No such file or directory)

This was for ~2000 requests and 60s duration.

Powered by GitHub Issue Mirror