Nginx, PHP-fpm и таймауты

Многих из нас интересует работа Nginx в паре с PHP-fpm и то, почему процессы прерываются а ошибок нет, я попробую рассказать об этом.

Итак, обычно, на следующие параметры не обращают внимание, а зря, ведь это базовые вещи, которые должны быть заданны в настройках, иначе они будут иметь дефолтное значение, или например одно значение может быть заданно, а второе нет:

nginx.conf fastcgi_read_timeout Количество секунд, которое будет ждать Nginx от PHP-fpm (задаёт таймаут при чтении ответа FastCGI-сервера). Таймаут устанавливается не на всю передачу ответа, а только между двумя операциями чтения. Если по истечении этого времени FastCGI-сервер ничего не передаст, соединение закрывается. По-умолчанию 60 секунд.
php-fpm.conf request_terminate_timeout Таймаут для обслуживания одного запроса, после чего рабочий процесс будет завершен. Этот вариант следует использовать, когда опция 'max_execution_time' в php.ini не останавливает выполнение скрипта по каким-то причинам. Значение '0' означает 'выключено'. Доступные единицы измерения: s(econds), m(inutes), h(ours) или d(ays). Значение по умолчанию: 0, т.е. никогда.

Значит, дефолтно, если php будет отдавать ответ более 60 секунд, то nginx закроет соединение и клиент получит 504 Gateway Time-out.

Если request_terminate_timeout сработает раньше чем fastcgi_read_timeout, то nginx выдаст: 502 Bad Gateway, в противном случае: 504 Gateway Time-out

Практика

1. Укажем количество секунд, которое будет ждать Nginx от PHP-fpm:

server {
    ...
    location ~ ^/app\.php(/|$) {
        ...
        fastcgi_read_timeout 3;
    }
}

2. В файл /etc/php5/fpm/php-fpm.conf добавляем таймауты нашего пула:

[site-local]

request_slowlog_timeout = 5s
request_terminate_timeout = 30s

3. Создаем PHP-файл /var/www/site/web/app.php с следующим содержимым:

<?php
$sleep = 0;
while($sleep < 35){
    $sleep++;
    sleep(1);
    file_put_contents('/var/www/site/sleep.log', $sleep.PHP_EOL, FILE_APPEND);
}

4. Выполняем запрос к нашему сайту:

curl -i http://site.local/info.json
HTTP/1.1 504 Gateway Time-out
Server: nginx/1.9.3 (Ubuntu)
Date: Wed, 27 Apr 2016 16:58:17 GMT
Content-Type: text/html
Content-Length: 191
Connection: keep-alive

<html>
<head><title>504 Gateway Time-out</title></head>
<body bgcolor="white">
<center><h1>504 Gateway Time-out</h1></center>
<hr><center>nginx/1.9.3 (Ubuntu)</center>
</body>
</html>

как видите, сработала настройка fastcgi_read_timeout.

5. Смотрим на то, что происходит в PHP-fpm:

# /usr/sbin/php5-fpm
[27-Apr-2016 16:56:35] NOTICE: fpm is running, pid 98
[27-Apr-2016 16:56:35] NOTICE: ready to handle connections
[27-Apr-2016 16:56:35] NOTICE: systemd monitor interval set to 10000ms

Обратите внимание, сработала php-fpm настройка request_slowlog_timeout:

[27-Apr-2016 16:58:16] ERROR: failed to ptrace(ATTACH) child 100: Operation not permitted (1)
[27-Apr-2016 16:58:16] WARNING: [pool site-local] child 100, script '/var/www/site/web/app.php' (request: "GET /app.php") executing too slow (5.385329 sec), logging

но, PHP-fpm-процесс все еще живет и выполняется (если в нем появляются ошибки, они будут записаны в логи).

Теперь внимание, сработала php-fpm настройка request_terminate_timeout:

[27-Apr-2016 16:58:44] WARNING: [pool site-local] child 100, script '/var/www/site/web/app.php' (request: "GET /app.php") execution timed out (30.382169 sec), terminating
[27-Apr-2016 16:58:44] WARNING: [pool site-local] child 100 exited on signal 15 (SIGTERM) after 129.988014 seconds from start

Все, после этой строки никаких ошибок Вы не увидите, т.к. PHP-fpm-процесс, обслуживающий запрос под номером 100, был убит.

Кстати: как видите лог-записи 2:

первая - говорит о том, какой скрипт отрабатывал и через сколько он был убит:

[27-Apr-2016 16:58:44] WARNING: [pool site-local] child 100, script '/var/www/site/web/app.php' (request: "GET /app.php") execution timed out (30.382169 sec), terminating

вторая - говорит о том, каким сигналом был убит дочерний пхп-фпм процесс и сколько времени он прожил (129 секунд - за это время он мог отработать ряд запросов, но увы текущий запрос был долгим, поэтому пхп-фпм принял решение убить процесс):

[27-Apr-2016 16:58:44] WARNING: [pool site-local] child 100 exited on signal 15 (SIGTERM) after 129.988014 seconds from start

внимание: у обоих записей child 100 (это ведь один реальный процесс)

Делаем вывод господа:

  1. В реальном проекте таймаут-параметры Nginx и PHP-fpm должны быть одинаковы (но не обязательно, главное чтобы в PHP-fpm был указан request_terminate_timeout)
  2. Собирайте статистику выполнения Nginx-запросов и если они достигают или превышают лимиты - оптимизируйте сайт или увеличивайте лимиты :)

Другие заметки

Ниже опишу дополнительные заметки

Неправильное ощущение

С какого-то времени PHP-fpm согласно таймауту стал завершать процессы сигналом 9:

WARNING: [pool www] child 28 exited on signal 9 (SIGKILL) after 207.053563 seconds from start

И я сразу подумал, что проблема в request_terminate_timeout, но причиной тому были настройка pm.max_requests=100

Если pm.max_requests указать больше 0, то php-fpm-master будет убивать php-fpm-kid процесс после того, как php-fpm-kid обслужил указанное кол-во http-запросов (в данном случае 100). Это конечно полезно для избежания утечек памяти при использовании сторонних библиотек. Для бесконечной обработки запросов укажите '0'. Эквивалент PHP_FCGI_MAX_REQUESTS. Значение по умолчанию: 0. 

Зависимость php-fpm от nginx

Говорят, можно завершать php-fpm процесс, если завершился nginx-процесс который его "породил". Это было бы очень правильной стратегией, потому что нет смысла тратить ресурсы/мощности сервера, если клиент уже не собирается получать ответ.

К сожалению, у меня это сделать не получилось, но пробовал я так:

  1. устанавливал "fastcgi_ignore_client_abort on" в nginx
  2. устанавливал ignore_user_abort(false); в php-скрипте

Клиент отказался ждать

Если клиент прервал соединение с nginx (раньше чем успел ответить php-fpm), то например при двух запросах, мы увидим такие access-логи:

nginx_1     | 172.18.0.1 - - [24/Aug/2021:10:22:20 +0000] "POST /api/v2/page HTTP/1.1" 499 0 "-" "-"
nginx_1     | 172.18.0.1 - - [24/Aug/2021:10:22:20 +0000] "POST /api/v2/page HTTP/1.1" 499 0 "-" "-"

php-fpm_1   | 172.18.0.4 -  24/Aug/2021:10:22:19 +0000 "POST /index.php" 200
php-fpm_1   | 172.18.0.4 -  24/Aug/2021:10:22:19 +0000 "POST /index.php" 200

Почему нельзя доверять max_execution_time

PHP когда считает время выполнения скрипта (и анализируя значение выставленное функцией set_time_limit() и директивой max_execution_time) не берет в расчет время, затраченное на различные действия вне скрипта, такие как системные вызовы функции system(), sleep(), потоковые операции, запросы к базам данных и т.п..

Например, если max_execution_time равен 30 секунд, при этом стоит sleep(10), то PHP остановит выполнение скрипта только по прошествии 40 секунд.

Мало того, если тайм-аут изначально был 30 секунд, и через 25 секунд после запуска скрипта будет вызвана функция set_time_limit(20), то скрипт будет работать максимум 45 секунд.

А еще к минусам можно отнести наличие hard_timeout которое продлевает max_execution_time на случай, если вдруг что-то застрянет (по умолчанию: 0).

Повторные обращения

Если nginx обращается к php-fpm по адресу localhost то адрес резолвится в 127.0.0.1 и [::1] (так оно и происходит обычно в k8s).
Таким образом запрос уходит на 127.0.0.1 и, в случае если php-fpm не ответил за fastcgi_read_time, вместо возврата 504 ошибки запрос повторно отправляется уже на [::1]. Следовательно, надо выключить это поведение вот так:

server {
    ...
    location ... {
       ...
       fastcgi_next_upstream off;
       ...
    }

Глюки

На проде сталкиваюсь с ситуацией, когда nginx чего-то ждет и выдает 5хх, даже при таких экспериментальных настройках:

fastcgi_read_timeout 30;
fastcgi_next_upstream off;

+ php.fpm:

request_terminate_timeout=12s

и единственное, что помогает, это перезапрос на балансировщике.

Удачки.


27.04.2016 16:59