CPU on server maxes out on almost every request

[oxyc]

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.

[Twansparant]

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!

[oxyc]

Looking at the last screenshot shows:

• 64 calls to myqli_query took 3.46s
• 518 calls to file_exists took 1.06s
• 305k calls to is_array() took 0.931s

All 3 of those are for sure wildly out of norm! To compare, one project I have has:

• 81k calls to is_array() in 0.044s.
• 20k calls to file_exists() in 2.8s (NFS so a lot faster on production, your is much slower than NFS though)

Some questions I would have and look into:

1. Which PHP version are you running?

2. What are the opcache, realpath* settings in php -i? I’m wondering if there’s some cache filling up.

3. 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.

4. 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?

5. 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

[Twansparant]

@oxyc

Which PHP version are you running?

1. We’re running PHP 8.0.15 on the local & remote servers

@oxyc

What are the opcache, realpath* settings in php -i? I’m wondering if there’s some cache filling up.

2. PHP opcache settings:

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

@oxyc

How much memory does the average process take

3. Not sure if the average process is actually ~30 Mb. When I log the backend with 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?

@oxyc

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?

4. Yes the frontend as well as the backend are both DO droplets:

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.

@oxyc

I assume there cant be 5511 fields

5. No there definitely aren’t 5511 fields, more like 50 or so.

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!

[oxyc]

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.

[Twansparant]

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!

[oxyc]

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.

[Twansparant]

@oxyc

Seems it’s at least related to AcfComposer Partials.

Maybe yes, I’m following this pattern, and have used it in several projects.

@oxyc

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.

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!

[Twansparant]

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…

[Twansparant]

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…

[oxyc]

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.

[joaovpmamede]

Has anyone found a solution for this problem?

[strarsis]

Not having experienced this issue (luckily), but would using a cache/object cache like Memcached or Redis reduce the performance hit as a workaround?

[MWDelaney]

I’m running into this issue on a random few sites. There’s no clear pattern to which sites are affected yet. Did anyone end up making progress here?

[ben]

Related newer topic:

Troubleshooting slow server response times

I’m working on a project that has grown quite complex and apparently slow. Local env: Lando (with xdebug) + Bedrock + Sage 10 (Acorn v3) Prod env: AWS EC2 (t3.medium) + Trellis (Ubuntu 20.04 deploy) As for the theme, I’ve been trying to keep the usage of unnecessary plugins to bare minimum, currently: ACF Pro, Gravity Forms, WooCommerce, WooCommerce Subscriptions, WP Rocket, WPML, Yoast SEO and a few other smaller ones that I don’t consider worth mentioning. Chrome Developer tools tell that …

I’m going to go ahead and lock this topic the majority of the discussion was related to a performance issue in acf-composer which was solved — please create new topics with as many details about your setups as possible