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

Improve performance by avoiding access() calls to non-existing files #14420

Closed
toredash opened this issue May 6, 2019 · 4 comments · Fixed by #14430, #14625 or matomo-org/tag-manager#166
Closed
Assignees
Labels
c: Performance For when we could improve the performance / speed of Matomo. Help wanted Beginner friendly issues or issues where we'd highly appreciate community's help and involvement.
Milestone

Comments

@toredash
Copy link
Contributor

toredash commented May 6, 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
Copy link
Member

tsteur commented May 6, 2019

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.

@tsteur tsteur added this to the 3.11.0 milestone May 6, 2019
@tsteur tsteur added the Help wanted Beginner friendly issues or issues where we'd highly appreciate community's help and involvement. label May 6, 2019
@toredash
Copy link
Contributor Author

toredash commented May 7, 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.

@katebutler katebutler self-assigned this May 7, 2019
@Findus23 Findus23 added the c: Performance For when we could improve the performance / speed of Matomo. label May 8, 2019
@Findus23 Findus23 changed the title Excessive access() calls to non-existing files [Performance] Excessive access() calls to non-existing files May 8, 2019
@toredash
Copy link
Contributor Author

toredash commented May 21, 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.

@tsteur
Copy link
Member

tsteur commented May 22, 2019

We would likely not add any more files. Maybe we could add some plugin files like Morpheus/Morpheus.php and CoreConsole/CoreConsole.php but any other ones we probably wouldn't add.

@mattab mattab modified the milestones: 3.11.0, 3.10.0 May 28, 2019
@mattab mattab changed the title Excessive access() calls to non-existing files Improve performance by avoiding access() calls to non-existing files Jun 29, 2019
toredash added a commit to toredash/matomo that referenced this issue Jul 4, 2019
toredash added a commit to toredash/matomo that referenced this issue Jul 4, 2019
toredash added a commit to toredash/tag-manager that referenced this issue Jul 4, 2019
tsteur pushed a commit to matomo-org/tag-manager that referenced this issue Jul 4, 2019
toredash added a commit to toredash/matomo that referenced this issue Aug 9, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
c: Performance For when we could improve the performance / speed of Matomo. Help wanted Beginner friendly issues or issues where we'd highly appreciate community's help and involvement.
Projects
None yet
5 participants