If you are using Acorn, then yes I’m able to confirm I’m experiencing a similar issue with the after_setup_theme
hook:
We’ll be investigating Acorn performance /cc @QWp6t
If you are using Acorn, then yes I’m able to confirm I’m experiencing a similar issue with the after_setup_theme
hook:
We’ll be investigating Acorn performance /cc @QWp6t
Yes we’re using the latest version of Acorn. I was also thinking in that direction (i’m @monokai’s colleague btw)
We’re using the same setup in an older project with sage9 without this performance issue, so I was thinking it was because of the inclusion of laravel indeed
Are you able to drilldown to which PHP functions consume highest exclusive time using Tideways? Since it’s a fork of XHProf and XHProf supports it I would suppose you can. Looks like it’s the Callgraph profiler 5. The Callgraph Profiler :: Documentation
Edit: are those values you show really milliseconds, that’s sort of insane. On a random site of mine the entire main() inclusive time is 600ms with latest acorn.
Since load_textdomain is 424ms it sounds like filesystem access is slow (is_readable, file_exists, composer functions etc)
Thanks a lot for calling out that profiler, this thing is incredibly helpful. Craig and I were digging into this a bit just now and will pick it up again shortly
For reference I have 2 calls to SplFileInfo::getRealPath on a pretty empty site with roots/acorn dev-main. 32 on another site. All calls from Illuminate\Foundation\Bootstrap\LoadConfiguration::getConfigurationFiles
Not stock sage though but I dont think there’s anything different really. Edit: Actually it is a FSE theme so it’s very different (doh), no template_include blade files.
In our case, we’re using the blade-icons
package with a couple different icon sets. We needed to run wp acorn icons:cache
and the performance issues were solved
@Twansparant @monokai have y’all had any luck digging deeper into the source of your issue?
If you aren’t using blade-icons, are you using another package that might have registered a command that would allow things to be cached? You can check by running wp acorn
and looking at the list of commands
Thanks, that IS a very useful tool indeed!
We’re only using log1x/acf-composer
& log1x/poet
in our theme.
What I don’t understand, is when I look at the timeline of the frontpage in our decoupled next.js page, each single call to the WP REST API through web/index.php is slow.
For example the first call:
/wp-json/clarify/v1/menu/main_menu takes 1.94 s!
But when I call that endpoint directly in the browser it’s only 118 ms?
When I inspect the Callgraph of that endpoint, I can see 271012 calls to:
RecursiveTransform::shouldRecurse
StoutLogic\AcfBuilder\Transform
Running wp acorn
results in:
Acorn 2.0.3 (Laravel 8.81.0)
USAGE: wp acorn <command> [options] [arguments]
clear-compiled Remove the compiled class file
completion Dump the shell completion script
env Display the current framework environment
help Display help for a command
list List commands
optimize Cache the framework bootstrap files
acf:block Create a new ACF block type.
acf:field Create a new ACF field group.
acf:options Create a new ACF options page.
acf:partial Create a new ACF field group partial.
acf:widget Create a new ACF sidebar widget.
acorn:init Initializes required paths in the base directory.
config:cache Create a cache file for faster configuration loading
config:clear Remove the configuration cache file
make:command Create a new Artisan command
make:component Create a new view component class
make:composer Create a new view composer class
make:provider Create a new service provider class
optimize:clear Remove the cached bootstrap files
package:discover Rebuild the cached package manifest
vendor:publish Publish any publishable assets from vendor packages
view:cache Compile all of the application's Blade templates
view:clear Clear all compiled view files
So not any specific ACF/StoutLogic caching commands?
Do you see anything that’s off?
I think our specific problem lies more in the fact that there are multiple API calls simultaneously, I also don’t exactly understand what the SQL WAIT
tags indicate? How can this be avoided?
EDIT:
When I inspect one of the SQL WAIT web/index.php
calls, the after_setup_theme
event takes a staggering 11.6 s:
Thanks!
What does the callgraph look like for the 11.6s page load?
That’s a bit harder to debug for me, it’s not working with the Google Chrome extension nor with the GET-parameters if I use the decoupled domain. This only works calling the CMS endpoints directly, but since 1 front-end page, calls multiple CMS endpoints I have to find another way to enable these callgraphs for multiple API calls.
Unfortunately I haven’t used Tideways beyond their XHProf fork back when it was the only one supporting php7. My guess would be that you need the PHP extension and a paid plan to get it profilin multiple API calls?
If you can test it locally, I find XHProf good at profiling, but not sure how to set that up with trellis. Personally i use DDEV which has it included.
Before that I used ansible-role-php-xhprof which probably works with trellis. You do need to add a webserver endpoint for it. With this setup I used a fork of wp-xhprof to initialize the profiling. But maybe wp-xhprof has been updated since then…
With XHProf it profiles each request as you browse the site and you can just browse through them after.
Thanks @oxyc for your reply!
I managed to append the Tideway Callgraph GET-parameters to all of my REST API calls in my frontend, this is how my average responses look like:
As you can see, each individual call takes somewhere between 1.8~3.4 s.
If I further inspect one of the slower calls (3.44s), I can see the after_setup_theme
takes 26.6 s (how’s that even possible)?
In the Callgraph overview, I don’t see anything weird; ACFBuilder has the slowest code paths:
In all of the responses, after_setup_theme
by far takes the longest in time…
Not sure how else to debug this?
Thanks!
Looking at the last screenshot shows:
All 3 of those are for sure wildly out of norm! To compare, one project I have has:
Some questions I would have and look into:
Which PHP version are you running?
What are the opcache, realpath* settings in php -i? I’m wondering if there’s some cache filling up.
How much memory does the average process take (not sure if we can trust tideways on this, is it really only ~30mb?). I’m wondering if max_children 40 consumes too much ram causing throttling. But if it’s really only 30mb than that would only be 1.2gb ram which should be fine.
Are these numbers from digitalocean droplets? It was mentioned the services were in docker containers, are the php files COPY:ed into the container or is there a mounted volume?
It says FieldManager::validateFieldName is called 5511 times, glancing at acf-builders code I feel like this should only run once per field. I assume there cant be 5511 fields, something wrong there?
It’s a difficult one to debug for sure… Too few CPU cores could cause this but you mentioned you already tried increasing it so… no
Opcode Caching | Up and Running |
---|---|
Optimization | Enabled |
SHM Cache | Enabled |
File Cache | Disabled |
JIT | Disabled |
Startup | OK |
Shared memory model | mmap |
Cache hits | 15787411 |
Cache misses | 4270 |
Used memory | 75550824 |
Free memory | 58665824 |
Wasted memory | 1080 |
Interned Strings Used memory | 6290992 |
Interned Strings Free memory | 0 |
Cached scripts | 3186 |
Cached keys | 5202 |
Max keys | 7963 |
OOM restarts | 0 |
Hash keys restarts | 0 |
Manual restarts | 0 |
Directive | Local Value | Master Value |
---|---|---|
opcache.blacklist_filename | no value | no value |
opcache.consistency_checks | 0 | 0 |
opcache.dups_fix | Off | Off |
opcache.enable | On | On |
opcache.enable_cli | On | On |
opcache.enable_file_override | Off | Off |
opcache.error_log | no value | no value |
opcache.file_cache | no value | no value |
opcache.file_cache_consistency_checks | On | On |
opcache.file_cache_only | Off | Off |
opcache.file_update_protection | 2 | 2 |
opcache.force_restart_timeout | 180 | 180 |
opcache.huge_code_pages | Off | Off |
opcache.interned_strings_buffer | 8 | 8 |
opcache.jit | tracing | tracing |
opcache.jit_bisect_limit | 0 | 0 |
opcache.jit_blacklist_root_trace | 16 | 16 |
opcache.jit_blacklist_side_trace | 8 | 8 |
opcache.jit_buffer_size | 0 | 0 |
opcache.jit_debug | 0 | 0 |
opcache.jit_hot_func | 127 | 127 |
opcache.jit_hot_loop | 64 | 64 |
opcache.jit_hot_return | 8 | 8 |
opcache.jit_hot_side_exit | 8 | 8 |
opcache.jit_max_exit_counters | 8192 | 8192 |
opcache.jit_max_loop_unrolls | 8 | 8 |
opcache.jit_max_polymorphic_calls | 2 | 2 |
opcache.jit_max_recursive_calls | 2 | 2 |
opcache.jit_max_recursive_returns | 2 | 2 |
opcache.jit_max_root_traces | 1024 | 1024 |
opcache.jit_max_side_traces | 128 | 128 |
opcache.jit_prof_threshold | 0.005 | 0.005 |
opcache.lockfile_path | /tmp | /tmp |
opcache.log_verbosity_level | 1 | 1 |
opcache.max_accelerated_files | 4000 | 4000 |
opcache.max_file_size | 0 | 0 |
opcache.max_wasted_percentage | 5 | 5 |
opcache.memory_consumption | 128 | 128 |
opcache.opt_debug_level | 0 | 0 |
opcache.optimization_level | 0x7FFEBFFF | 0x7FFEBFFF |
opcache.preferred_memory_model | no value | no value |
opcache.preload | no value | no value |
opcache.preload_user | no value | no value |
opcache.protect_memory | Off | Off |
opcache.record_warnings | Off | Off |
opcache.restrict_api | no value | no value |
opcache.revalidate_freq | 60 | 60 |
opcache.revalidate_path | Off | Off |
opcache.save_comments | On | On |
opcache.use_cwd | On | On |
opcache.validate_permission | Off | Off |
opcache.validate_root | Off | Off |
opcache.validate_timestamps | On | On |
PHP realpath settings:
realpath_cache_size => 4096K => 4096K
realpath_cache_ttl => 120 => 120
htop
and do a frontend refresh I can see lots of php-fpm
processes coming in and maxing out the CPU, which was the reason to start this thread: CPU[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||100.0%] Tasks: 77, 61 thr; 1 running
Mem[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| 1014M/1.94G] Load average: 5.21 2.78 2.78
Swp[|||||| 49.8M/954M] Uptime: 10 days, 18:24:58
PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command
153186 web 20 0 252M 98372 72500 R 6.2 4.8 0:01.35 php-fpm: pool wordpress
153188 web 20 0 251M 96428 71196 R 6.2 4.7 0:01.22 php-fpm: pool wordpress
153190 web 20 0 249M 96372 71504 R 6.2 4.7 0:01.21 php-fpm: pool wordpress
153184 web 20 0 249M 96352 71504 R 6.2 4.7 0:01.23 php-fpm: pool wordpress
153181 web 20 0 251M 95700 70608 R 6.2 4.7 0:01.20 php-fpm: pool wordpress
153327 web 20 0 247M 73664 53600 R 6.2 3.6 0:00.12 php-fpm: pool wordpress
153328 web 20 0 245M 72592 53600 R 6.2 3.6 0:00.12 php-fpm: pool wordpress
153329 web 20 0 247M 73644 53600 R 6.2 3.6 0:00.12 php-fpm: pool wordpress
153343 web 20 0 239M 58732 46104 R 6.2 2.9 0:00.05 php-fpm: pool wordpress
153173 web 20 0 251M 95724 70632 R 0.0 4.7 0:01.22 php-fpm: pool wordpress
153192 web 20 0 249M 96308 71504 R 0.0 4.7 0:01.23 php-fpm: pool wordpress
153189 web 20 0 249M 96364 71504 R 0.0 4.7 0:01.23 php-fpm: pool wordpress
153183 web 20 0 249M 96356 71504 R 0.0 4.7 0:01.22 php-fpm: pool wordpress
153182 web 20 0 251M 96420 71196 R 0.0 4.7 0:01.22 php-fpm: pool wordpress
153185 web 20 0 251M 96628 71504 R 0.0 4.8 0:01.21 php-fpm: pool wordpress
153180 web 20 0 249M 96300 71504 R 0.0 4.7 0:01.20 php-fpm: pool wordpress
153326 web 20 0 249M 76640 54520 R 0.0 3.8 0:00.15 php-fpm: pool wordpress
153334 web 20 0 241M 66132 50636 R 0.0 3.3 0:00.08 php-fpm: pool wordpress
153337 web 20 0 241M 66216 50700 R 0.0 3.3 0:00.08 php-fpm: pool wordpress
153324 web 20 0 249M 80252 57460 R 0.0 4.0 0:00.19 php-fpm: pool wordpress
153330 web 20 0 247M 73908 53600 R 0.0 3.6 0:00.12 php-fpm: pool wordpress
153336 web 20 0 241M 66200 50700 R 0.0 3.3 0:00.08 php-fpm: pool wordpress
153339 root 20 0 239M 58720 46104 R 0.0 2.9 0:00.05 php-fpm: master process (/etc/php/8.0/fpm/php-fpm.conf)
153341 root 20 0 239M 58720 46104 R 0.0 2.9 0:00.05 php-fpm: master process (/etc/php/8.0/fpm/php-fpm.conf)
153177 web 20 0 251M 96812 71488 R 0.0 4.8 0:01.24 php-fpm: pool wordpress
153191 web 20 0 251M 96608 71504 R 0.0 4.8 0:01.23 php-fpm: pool wordpress
153332 web 20 0 241M 65864 50508 R 0.0 3.2 0:00.08 php-fpm: pool wordpress
153333 web 20 0 241M 66220 50700 R 0.0 3.3 0:00.08 php-fpm: pool wordpress
Since the logs displayed a suggestion:
[pool wordpress] server reached pm.max_children setting (10), consider raising it
We increased the max_children
to 40, do you think this is too hight now?
I also noticed the VIRT column never exceeds the 256M while the memory_limit
is set to 512M?
Frontend Docker: 1 GB / 1 vCPU
Backend Trellis: 2 GB / 1 AMD vCPU
Could the AMD processors somehow be causing any of these issues?
Only the frontend is running in a docker container without php, just node.
We did try increasing the production droplet to: 2 GB / 2 AMD vCPUs and it did solve the problem slightly, but the CPU still spikes to 100% on both on a simple frontend page load.
I think the big difference is that we’re using our Sage 10 theme only as an API provider with tools like acf-composer
& poet
.
On a frontend page load, multiple REST API request are made (at least 5, but could be 10) and we can see those are clogging up the memory and response times, the first request is ok, 2nd is already slower and 3rd one even more.
Basically on every API request the \Roots\bootloader is trying to load the Laravel framework, which for us, is only required so we can use acf-composer
& poet
.
Could that be the cullprit?
Thanks!
I just checked a site with AcfBuilder and can confirm FieldManager::validateFieldName
was only called once per field. 40 calls with ~5 blocks using ACF blocks and it sounds about right.
Everything in your setup looks correct to me so maybe I’m underestimating the CPU usage. Could you check what the call chain to FieldManager::validateFieldName
is? When does it explode to 5000 calls?
How many calls are there to StoutLogic\AcfBuilder\ParentDelegationBuilder::__call
for example?
I have 27 calls.
I would look at why AcfBuilder triggers so many function calls. Based on your last screenshot at least 9 out of 16 of the most time consuming functions are triggered by AcfBuilder.
It’s hard to tell where it explodes to be honest? I have a flexible content field that loads different modules with partials, so maybe it happens there?
Looking at the callgraph RecursiveTransform::shouldRecurse
has 271012 calls and is_array
even has 305425? This is the drilldown for the shouldRecurse call:
RecursiveTransform::shouldTransformValue
also has 76762 and FieldManager::validateFieldName
has 5511:
This is the drilldown for the validateFieldName call:
For all of the calls, the biggest delay is still between wp-load.php
& do_action('after_setup_theme')
, almost 3 seconds every time?
Thanks for your time so far, I really appreciate it!
Seems it’s at least related to AcfComposer Partials.
I’m assuming there should not be 96 calls to Video::fields. I’ve actually only used AcfComposer with blocks and not fields/partials so not really sure how it works. If it was a block, Video::fields would only have been called once.
I can also see PageModules::fields
is correctly called once but Modules::fields
is called twice, MediaColumns::fields
four times and finally Video::fields
96 times.
Maybe yes, I’m following this pattern, and have used it in several projects.
I don’t understand why Modules::fields
is called twice, it’s only used as partial once in PageModules::fields
which is only used once on the front page? The MediaColumns::fields
could be added as flexible content multiple times, so 4 times seems fine. The Video::fields
partial is included twice in the MediaColumns
partial, so that should be 8 times not 96…
I need to investigate this further… Could be that it’s related to how we format the ACF relationship field values on the front page to other posts, which also could have a lot of acf fields again.
I’ll report back here!
One thing I haven’t mentioned yet is the fact that our remote servers are using DO managed databases? Could this be the source of slow responses: Managed DB become very very slow | DigitalOcean
EDIT: I just re-provisioned my staging server using the default local maria-db, but same results. Even a bit slower it seems…
In the meantime I submitted a bug report over at Log1x/acf-composer since it might be related with Acorn & acf-composer.
If I redefine my ACF fields using this older guide using StoutLogic\AcfBuilder\FieldsBuilder
directly it improves the performance drastically.
The partials are only called once for each include and the after_setup_theme
event has decreased to an average of below 2.0 s .
Not sure what might be causing this though…
Any chance you could test it in a different environment than DO?
With the fix you talked about over in the acf-composer issue, maybe reduce your php max_children and servers and test again using 4 cpus. My thinking is that the php workers are fighting over resources and distort the performance numbers with a lack of cpu cores and waiting for MySQL to get the thread.