CPU on server maxes out on almost every request

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:

  • 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

3 Likes
  1. We’re running PHP 8.0.15 on the local & remote servers
  1. 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
  1. 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?

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

  1. 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!

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.

1 Like

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!

2 Likes

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…

1 Like

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.

Has anyone found a solution for this problem?

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

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?

1 Like

Related newer topic:

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

1 Like