Edit report at https://bugs.php.net/bug.php?id=75488&edit=1
ID: 75488
User updated by: david at davidfavor dot com
Reported by: david at davidfavor dot com
Summary: Under heavy load PHP misses Opcache hits with no
errors
Status: Open
Type: Bug
Package: opcache
Operating System: Ubuntu Zesty
PHP Version: 7.1.11
Block user comment: N
Private report: N
New Comment:
Steps to reproduce.
Config settings + opcache data links...
http://144.217.34.1/wptools/phpinfo.php
http://144.217.34.1/wptools/ocp-0.2.0.php
1) set opcache.ini values to never revalidate
#opcache.revalidate_freq=0
#opcache.validate_timestamps=0
#opcache.enable_file_override=0
lxd: net11-david-favor # service php7.1-fpm restart
lxd: net11-david-favor # truncate -s 0 /var/log/php7.1-fpm/access.log
2) Initiate a simple load test...
lxd: net11-david-favor # h2load -ph2c -t16 -c16 -m16 -n200000 https://net11.heartbeat.davidfavor.com/hello.php
... ... ...
finished in 11.29s, 17719.92 req/s, 2.06MB/s
requests: 200000 total, 200000 started, 200000 done, 200000 succeeded, 0 failed, 0 errored, 0
timeout
status codes: 200000 2xx, 0 3xx, 0 4xx, 0 5xx
This works as expected. 200000 started. 200000 successes. 0 failures.
3) Count log entries...
lxd: net11-david-favor # egrep -e hello.php /var/log/php7.1-fpm/access.log | wc -l
200000
4) Count log entries != 0.00%, so this could shows non-cached PHP executions. This count should be
1, as the .php file should run once + then be cached + come out of cache forever, since revalidate
is off.
lxd: net11-david-favor # egrep -e hello.php /var/log/php7.1-fpm/access.log | egrep -v -e "
0.00%" | wc -l
5098
5) Now check opcache data...
Opcache shows 2 misses + 195K hits, which is wrong.
Should be 5098 misses + 194K hits.
This problem is reproducible 100% of the time.
6) After thought.
Now 3% breakage on 200K requests might seem inconsequential.
The problem occurs on high traffic sites, so say 100+ WordPress post slugs with sustained traffic of
50K-100K/second visits.
These are the numbers on the client site I host which surfaced the problem.
When this breakage begins on various page requests, which involve man .php files, the entire site
begins to circle the drain quickly. Here's an example of why.
Consider these crazy numbers from a random snippet of FPM log entries.
1) hello.php 5.863 2048 170.56%
2) hello.php 1.468 2048 681.20%
3) hello.php 1.695 2048 589.97%
4) hello.php 0.217 2048 4608.29%
5) hello.php 0.228 2048 4385.96%
6) hello.php 0.148 2048 0.00%
These entries show milliseconds to execute + memory usage + CPU usage.
Item #1 - Seriously bad 5.8 seconds to finish, with low CPU usage. This means an FPM thread is tied
up for 5.8 seconds, so site death will surely occur, with high traffic.
Item #4 + #5 - FPM threads finish quickly + they hammer the CPU.
Item #6 - What should occur with every request. Fast execution time + 0.00% CPU usage, as the only
operation should be an opcache lookup + data return.
7) WordPress workaround.
In WordPress the work around is to use a caching plugin which utilizes mod_rewrite correctly.
Currently WP Super Cache is broken, so files are returned by Apache from file cache, then the
original request leaks through to PHP, so site dies because of this bug.
WP Fastest Cache does fix this problem, because files are returned by Apache from file cache + them
short circuited/stopped, so request terminates without hitting PHP.
High traffic PHP sites must work around this bug to survive right now, which requires a good bit of
expertise to resolve for non-WordPress sites, which have no simple mod_rewrite caching options.
I'm happy to provide any developer with root ssh access to the LXD container where this bug can
be worked + fixed.
Previous Comments:
------------------------------------------------------------------------
[2017-11-06 03:20:43] david at davidfavor dot com
Description:
------------
1) Create a simple hello.php (Hello World) file.
2) Run the following...
while : ; do curl -s -I -L https://foo.com/hello.php
>/dev/null ; done
3) Track FPM access log.
First all's well. 100% cache hits + FPM access log shows 0.00% CPU time for script execution.
Then odd behavior begins.
First huge CPU time number begin, ranging from 1-10+ seconds.
Looking at Opcache stats, 99% hits for a few minutes.
Then cache hit rate begins to drop also.
I've setup opcache logging with log verbosity == 4 + nothing useful comes out.
No Apache to FPM communication errors logged.
No FPM errors logged (running in at debug level).
No FPM slow log entries.
I've gone through Opcache config + see no setting which might explain this.
I'm using the ondrej:php + ondrej:apache2 PPAs so,
Apache-2.4.29-0.1 + PHP-7.1.11-1 are my versions.
My... Command Line Kung Fu is strong... so if someone can suggest how to debug this deeper, let me
know.
Test script:
---------------
<html>
<head>
<title>PHP Test</title>
</head>
<body>
<?php echo '<p>Hello World</p>'; ?>
</body>
</html>
Expected result:
----------------
Expected result 100% cache hits.
Actual result:
--------------
Roughly 1 out of 30ish requests fail to come from cache.
------------------------------------------------------------------------
--
Edit this bug report at https://bugs.php.net/bug.php?id=75488&edit=1