Swapping Apache and mod_php for nginx and PHP-FPM

The box is a 512 MB VPS. On an ordinary afternoon it serves a few thousand page views without noticing. On the afternoon a newsletter goes out it stops answering for about ninety seconds, and the graph that explains it is not the CPU one — CPU sits at around 35% the whole time. It is memory, and the reason is that a request for a 4 KB logo is being answered by a process carrying a complete PHP interpreter.

The symptom

$ free -m
             total       used       free     shared    buffers     cached
Mem:           496        487          9          0          2         31
Swap:          511        338        173

$ ps -ylC apache2 --sort:rss | tail -1
S  33  9144  8901  1  80   0  30112 116402 -  ?  0:02 /usr/sbin/apache2

$ pgrep -c apache2
41

Forty-one workers at roughly 29 MB resident each: 1.1 GB of intent on a machine with 496 MB. It is not instantly fatal only because much of each worker is shared — the binary, the modules, the APC segment. The unshared part is still around 9 MB, which is 370 MB of private memory on a box whose real working set is one application and a MySQL instance that wants the rest.

$ ps -C apache2 -o rss= | awk '{ s += $1 } END { print s / NR / 1024, "MB avg" }'
28.6 MB avg

$ grep -A2 MaxClients /etc/apache2/apache2.conf | head -3
    MaxClients          40
    MaxRequestsPerChild 500

MaxClients 40 is not a wrong number — it is the number somebody arrived at by lowering it until the swapping stopped. It is also the site’s concurrency ceiling, and forty is not many when one page makes eleven requests for static assets and each occupies a worker for a round trip to a phone on a bad connection.

Why it happens

Apache’s prefork MPM answers each connection from a separate process, and mod_php lives inside that process. There is no distinction between a request that will execute PHP and one that will read a file off disk and hand it back — both are served by something carrying the whole interpreter, every loaded extension, and whatever the previous script left behind in it.

# /etc/apache2/apache2.conf
<IfModule mpm_prefork_module>
    MinSpareServers       5
    MaxSpareServers      10
    MaxClients           40
    MaxRequestsPerChild 500
</IfModule>
# and, inside every one of those processes:
LoadModule php5_module /usr/lib/apache2/modules/libphp5.so

That is the entire mechanism, and it is why the problem has two halves that can be attacked separately: stop serving static files from a process containing PHP, then stop PHP living inside the web server at all. The note on mod_php and Apache workers covers the first half; this is both of them on a live site.

The fix

Stage one: nginx in front, Apache moved to 8080

The reversible step first. nginx takes port 80, serves anything that exists on disk, and proxies everything else to Apache, which now listens on 127.0.0.1:8080 and is otherwise untouched — same vhosts, same modules, same .htaccess files, same mod_php. If it goes badly, nginx stops and Apache goes back to port 80, and that is a two-line change at two in the morning.

server {
    listen 80;
    server_name shop.example.com;
    root /var/www/shop;

    # anything on disk is answered here and never reaches Apache
    location ~* .(jpe?g|png|gif|ico|css|js|pdf|woff)$ {
        expires 30d;
        access_log off;
        try_files $uri =404;
    }

    location / {
        proxy_pass http://127.0.0.1:8080;
        proxy_set_header Host              $host;
        proxy_set_header X-Real-IP         $remote_addr;
        proxy_set_header X-Forwarded-For   $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto $scheme;
    }
}

Apache now only sees what nginx could not satisfy from disk, which on this site is about one request in nine. That means MaxClients comes down rather than up: forty workers were sized for a request mix that no longer exists, and fifteen is generous for the mix that remains.

The thing that breaks immediately is logging. Every line in the Apache access log now says 127.0.0.1, so the stats page and the fail2ban rules reading it stop working the same afternoon. Apache needs mod_rpaf, or at least a LogFormat using %{X-Forwarded-For}i, before the proxy goes in.

$ free -m
             total       used       free     shared    buffers     cached
Mem:           496        392        104          0          9        112
Swap:          511         84        427
$ pgrep -c apache2
16

The swap already there does not clear — the kernel is in no hurry to page it back in — but nothing new goes to it, and the file cache has 112 MB it did not have before. That is one afternoon of work and most of the total benefit. Everything after it is smaller, and worth doing anyway, because PHP is still living inside a web server.

Stage two: PHP-FPM, and Apache leaves

PHP-FPM has been in the PHP core since 5.3.3 and on this box it is a package install. It runs a pool of PHP processes with no web server wrapped around them, and nginx talks to it over FastCGI. The switch itself is uninteresting. What matters is that pool sizing becomes an explicit decision, and the shipped configuration makes that decision badly.

; /etc/php5/fpm/pool.d/shop.conf
[shop]
user  = shop
group = shop

listen       = /var/run/php5-fpm.shop.sock
listen.owner = www-data
pm                 = dynamic
pm.max_children      = 8
pm.start_servers     = 3
pm.min_spare_servers = 2
pm.max_spare_servers = 4
pm.max_requests      = 500

request_terminate_timeout = 60s

pm.max_children is the whole configuration. It is the maximum number of PHP processes, which makes it the maximum number of concurrent PHP requests, and it should be derived from memory rather than copied out of a tutorial. Measure a worker under real load, leave the database what it needs, divide.

$ ps -C php5-fpm -o rss= | awk '{ s += $1 } END { print s / NR / 1024 }'
31.4

# 496 total - 180 mysql - 40 system - 20 nginx = 256 MB left for PHP
# 256 / 31.4 = 8

Eight. That is a fifth of the forty Apache workers it replaces and it is not a reduction in capacity, because the forty were mostly serving images. Eight concurrent PHP requests against a slowest page of 180 ms is something like forty-four requests a second, which this site has never been anywhere near.

pm.max_requests recycles a worker after 500 requests, which is a leak mitigation rather than a fix and hides the problem well enough that nobody looks for it again. request_terminate_timeout is the setting that saves the box: without it one script blocked on an external HTTP call holds a child indefinitely, and eight of those is the whole pool.

Stage three: translating the .htaccess files

There are five of them. nginx has no equivalent and will not read them, so each one has to be opened, understood and rewritten into the server block. This is the first time in four years anybody has read them.

# /var/www/shop/.htaccess
RewriteEngine On
RewriteCond %{REQUEST_FILENAME} !-f
RewriteCond %{REQUEST_FILENAME} !-d
RewriteRule ^(.*)$ index.php?/$1 [L]
php_flag  register_globals off
php_value upload_max_filesize 20M
<Files ~ "^.ht">
    Deny from all
</Files>

location / {
    try_files $uri $uri/ /index.php?$args;
}

# the Files block above, which nginx will not read from a directory
location ~ /. {
    deny all;
}

location ~ .php$ {
    try_files $uri =404;
    fastcgi_pass unix:/var/run/php5-fpm.shop.sock;
    include fastcgi_params;
    fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
}

Two of the eleven rules across those five files had been doing nothing. php_flag register_globals off names a directive PHP removed in 5.4, which this box has run since March, so it had been inert for seven months with no way for anyone to notice — an .htaccess rule that stops applying does so silently. The other protected an admin script under a filename changed in 2010.

The try_files $uri =404; line inside the PHP location is not tidiness. With cgi.fix_pathinfo=1, the default, FPM walks backwards up the path looking for a file that exists, so /uploads/avatar.jpg/x.php executes the uploaded JPEG as PHP. On a site that accepts uploads that is remote code execution, created by this migration rather than inherited.

What mod_php was quietly doing

Per-directory PHP settings are gone. php_value and php_flag in an .htaccess file were a mod_php feature with no FastCGI equivalent, which matters here because the upload directory had its limit raised that way. There are two replacements and they are not interchangeable:

; in the pool — the application cannot override these at runtime
php_admin_value[upload_max_filesize] = 20M
php_admin_value[post_max_size]       = 21M
php_admin_flag[display_errors]       = off

; or per directory, in uploads/.user.ini, for PHP_INI_PERDIR settings only
upload_max_filesize = 20M

.user.ini is the closer analogue, a 5.3 feature that exists for precisely this. It is also cached for user_ini.cache_ttl seconds — five minutes by default — so a change does not take effect immediately, which is a difference from .htaccess that will confuse somebody at least once.

The rest of the losses are in $_SERVER. apache_request_headers() does not exist outside mod_php, so anything reading a custom header goes through $_SERVER['HTTP_*'] instead, and REDIRECT_URL is not set. An Authorization header is not passed to FastCGI unless nginx is told to, which broke the one endpoint using basic authentication: a missing credential and a stripped one produce the same clean 401.

The slow log is the part worth keeping

FPM has one feature Apache never had, and on its own it would have justified the move. Given a threshold, it writes a PHP backtrace for any request that exceeds it. Not a URL and a duration — the actual stack, with files and line numbers, taken while the request is still running.

slowlog                 = /var/log/php5-fpm/shop.slow.log
request_slowlog_timeout = 3s
catch_workers_output    = yes

[23-Oct-2012 14:07:41]  [pool shop] pid 3391
script_filename = /var/www/shop/index.php
[0x00007f1b2c0] curl_exec()  /var/www/shop/application/libraries/Feed.php:88
[0x00007f1b2a0] fetch()      /var/www/shop/application/libraries/Feed.php:41
[0x00007f1b280] rates()      /var/www/shop/application/models/Price_model.php:212
[0x00007f1b260] convert()    /var/www/shop/application/views/product.php:64

A currency rate lookup, called from inside a view, making an uncached HTTP request in the middle of rendering the page. It had been there for two years and had never appeared in anything, because the product page was “a bit slow” rather than broken. No amount of free -m finds that. The slow log found it on its first day.

Verifying it worked

# same newsletter, one month on
$ free -m
             total       used       free     shared    buffers     cached
Mem:           496        421         75          0         18        196
Swap:          511          0        511
$ pgrep -c php5-fpm
9
$ ab -n 200 -c 20 http://shop.example.com/ | grep -E 'Failed|Time per'
Failed requests:        0
Time per request:       94.112 [ms] (mean)

Swap at zero under a load that used to push 338 MB into it, and 196 MB in the page cache doing something useful. Time to first byte went from 480 ms to 94 ms — but roughly 300 ms of that is not nginx at all. It is the currency lookup the slow log turned up, now held in APC. The honest split is that the web server bought the memory and the slow log bought the latency.

The memory went to MySQL. innodb_buffer_pool_size moved from 48 MB to 160 MB, which puts the catalogue’s working set entirely in memory, and that is quite possibly worth more than everything above it put together.

What this costs

.htaccess is gone and not coming back. Every rule now lives in a file only root can edit, and takes effect only after a reload. Where a redirect used to be added by dropping a line into a file over FTP, that is a real loss of speed — and refusing to admit it is how the next redirect ends up hardcoded in PHP.

There are two configuration languages now rather than one, and the nginx one is unforgiving in a specific way: location blocks match in an order of precedence that is not the order they are written in, so a rule that looks correct can be shadowed and never fire. nginx -t checks the syntax; it has no opinion about the intent.

And this was done on a live site over about six weeks, in three stages, each of which could be undone on its own. I would not attempt it in one evening, and I am not sure the second and third stages are worth it on every box. The first one is: nginx in front of an untouched Apache is reversible, takes an afternoon, and on this machine it was worth more than the two stages after it combined.