Недавно мы перенесли давно работающий (без проблем) стек Ubuntu 16.04 / nginx (1.10.3) / PHP 7.0 на стек Ubuntu 18.04 / nginx (1.14.0) / PHP 7.2. Результат вызвал нестабильность на уровне PHP-FPM, которой раньше никогда не было, и часы исследования не подтвердили никаких результатов в отношении основной причины проблемы.

Кстати, оба развертывания управляются через AWS, и в обеих ситуациях запускаемое приложение PHP использует идентичный код и подключается к одной и той же конечной точке MySQL RDS.

Проблема

После обновления система работает в обычном режиме в течение нескольких часов (иногда более 24 часов) без проблем. Внезапно, в считанные минуты, FPM начинает регистрировать предупреждения о том, что выполнение сценария истекло для различных дочерних элементов, например:

[15-Jul-2020 19:50:22] WARNING: [pool www] child 29649, script '/path/to/app.php' (request: "POST /app.php") execution timed out (140.371526 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25847, script '/path/to/app.php' (request: "GET /app.php") execution timed out (136.178758 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (135.822576 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25401, script '/path/to/app.php' (request: "POST /app.php") execution timed out (135.927461 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25229, script '/path/to/app.php' (request: "GET /app.php") execution timed out (143.179479 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25110, script '/path/to/app.php' (request: "POST /app.php") execution timed out (141.080509 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24904, script '/path/to/app.php' (request: "POST /app.php") execution timed out (142.441526 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24679, script '/path/to/app.php' (request: "GET /app.php") execution timed out (138.165572 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 24652, script '/path/to/app.php' (request: "POST /app.php") execution timed out (142.414685 sec), terminating
[15-Jul-2020 19:50:22] WARNING: [pool www] child 15982, script '/path/to/app.php' (request: "GET /app.php") execution timed out (125.469362 sec), terminating

Вскоре после этого FPM начинает порождать новых потомков, чтобы попытаться справиться с нагрузкой от nginx.

[15-Jul-2020 19:50:37] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 8 children, there are 0 idle, and 46 total children
[15-Jul-2020 19:50:38] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 16 children, there are 1 idle, and 51 total children
[15-Jul-2020 19:50:39] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 55 total children
[15-Jul-2020 19:50:40] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 60 total children
[15-Jul-2020 19:50:41] WARNING: [pool www] seems busy (you may need to increase pm.start_servers, or pm.min/max_spare_servers), spawning 32 children, there are 0 idle, and 65 total children

Затем, как только предел достигнут, сервер достигает максимальной емкости в 70 дочерних элементов, и FPM перестает принимать запросы от nginx ([error] 1072#1072: *234300 connect() to unix:/run/php/php7.2-fpm.sock failed (11: Resource temporarily unavailable) while connecting to upstream), в результате чего 502 ошибки.

[15-Jul-2020 19:50:42] WARNING: [pool www] server reached pm.max_children setting (70), consider raising it  

С этой точки зрения, приложение фактически не работает, пока служба FPM не будет перезапущена. При перезапуске FPM зависшие запросы / процессы немедленно завершаются, и проблема мгновенно решается на время.

Примечание: Важно отметить, что приложение обычно может работать с <= 10 рабочими, даже в часы пик, поэтому тот факт, что он мгновенно масштабируется из-за длительных процессов, безусловно, является ненормальным.

Повторение журналов для одного и того же идентификатора процесса

На первый взгляд журналы выглядят случайными, но если вы отфильтруете их по идентификатору дочернего процесса, становится ясно, что каждый дочерний процесс снова и снова пытается завершить один запрос. Более того, каждая запись в журнале для данного идентификатора процесса составляет ~ 40 секунд, о чем свидетельствует сравнение отметки времени в начале каждого журнала с соответствующим временем сценария в конце каждого журнала. Здесь я отфильтровал журнал по определенному идентификатору процесса для примера:

[15-Jul-2020 19:40:39] NOTICE: [pool www] child 25617 started
[15-Jul-2020 19:50:22] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (135.847853 sec), terminating
[15-Jul-2020 19:51:03] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (176.182362 sec), terminating
[15-Jul-2020 19:51:43] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (216.516705 sec), terminating
[15-Jul-2020 19:52:23] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (256.849969 sec), terminating
[15-Jul-2020 19:53:04] WARNING: [pool www] child 25617, script '/path/to/app.php' (request: "GET /app.php") execution timed out (297.183892 sec), terminating

Происходит, когда трафик увеличивается или находится на пике

Судя по времени суток, когда проблема возникает, вполне очевидно, что проблема предсказуемо возникает при увеличении трафика. Так, например, проблема возникает первым делом утром или в пик дня, когда трафик высок. Мы не наблюдали, чтобы эта проблема возникала при более низком трафике, например, посреди ночи.

Новая реликвия установлена

Новый демон relic устанавливается в обоих развертываниях через их репозиторий apt в соответствии с рекомендуемый способ установки изложены на их сайте.

   CGroup: /system.slice/php7.2-fpm.service
           ├─ 6554 php-fpm: master process (/etc/php/7.2/fpm/php-fpm.conf)
           ├─ 6583 /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /var/log/newrelic/newrelic-daemon.log --port @newrelic --wait-for-port 0s --define utilization.detect_aws=true --define utilization.de
           ├─ 6603 /usr/bin/newrelic-daemon --agent --pidfile /var/run/newrelic-daemon.pid --logfile /var/log/newrelic/newrelic-daemon.log --port @newrelic --wait-for-port 0s --define utilization.detect_aws=true --define utilization.de
           ├─ 7228 php-fpm: pool www
           ├─ 7520 php-fpm: pool www
           ├─ 7548 php-fpm: pool www
           ├─ 7569 php-fpm: pool www
           ├─11835 php-fpm: pool www
           ├─11944 php-fpm: pool www
           ├─11997 php-fpm: pool www
           ├─12106 php-fpm: pool www
           ├─12934 php-fpm: pool www
           └─13049 php-fpm: pool www

Примечание: Мы еще не пытались отключить новый агент реликвии, и это не кажется на первый взгляд связанной причиной.

Конфигурация пула FPM

Вот конфигурация пула, она же используется в обоих стеках:

pm = dynamic
pm.max_children = 70
pm.start_servers = 5
pm.min_spare_servers = 5
pm.max_spare_servers = 10
pm.max_requests = 1000

Конфигурация Nginx

В обоих развертываниях используется одна и та же конфигурация nginx.

user www-data;
worker_processes auto;
pid /run/nginx.pid;

events {
  worker_connections 2048;
}

http {
  include /etc/nginx/mime.types;
  default_type application/octet-stream;

  client_max_body_size 24m;
  sendfile on;
  tcp_nopush on;
  tcp_nodelay on;
  keepalive_timeout 120;
  limit_req_status 429;
  limit_req_zone $http_x_forwarded_for zone=web:16m rate=10r/s;
  types_hash_max_size 2048;
  server_tokens off;
  ssl_protocols TLSv1.2;
  ssl_prefer_server_ciphers on;
  gzip on;
  gzip_disable "msie6";
  gzip_vary on;
  gzip_proxied any;
  gzip_comp_level 6;
  gzip_buffers 16 8k;
  gzip_http_version 1.1;
  gzip_min_length 256;
  gzip_types text/plain text/css application/json application/javascript text/xml application/xml text/javascript image/x-icon;
  log_format main '$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" - $request_time X-Forwarded-For=$http_x_forwarded_for Host=$host';

  include /etc/nginx/conf.d/*.conf;
  include /etc/nginx/sites-enabled/*;
}

Конфигурация PHP

В обоих развертываниях используется одна и та же конфигурация, все остальные настройки оставлены по умолчанию.

max_execution_time=120
max_input_vars=5000
memory_limit=256M
post_max_size=24M

То, что мы пробовали и / или смотрели

• Мы попытались настроить конфигурацию пула FPM, чтобы включить request_terminate_timeout = 121 (сразу за max_execution_time установлен в php), в надежде, что это остановит эти застрял процессы, но это не сработало. Процессы продолжают быть terminating каждые 40 секунд, иногда более 1000 секунд.

• Основная конфигурация FPM остается по умолчанию без изменений, по умолчанию php-fpm.conf config в обеих версиях FPM абсолютно одинаков. Мы изучили emergency_restart_threshold, emergency_restart_interval и process_control_timeout конфигураций, но они, похоже, не являются фактором проблемы, с которой мы сталкиваемся.

• Возврат приложения обратно к Ubuntu 16.04 (PHP 7.0.33) волшебным образом решает проблему, но, очевидно, не то, что мы пытаемся решить путем обновления.

• Перезапуск FPM, когда он seems busy (через логи) решает проблему, но опять же не решение.

• Изучено ведение журнала внешнего интерфейса на предмет возможности случайных атак DOS, но трафик не является необычным.

• Изучены журналы ошибок nginx / php на наличие признаков того, что скрипты не завершаются должным образом (т.е. нет ответа). Ничего не найдено.

Вывод

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

Мы не исключаем, что проблема также может быть проблемой в самом приложении, но тот факт, что оно работает без проблем в предыдущей версии OS / PHP / FPM, будет указывать на несовместимость на уровне PHP, и пока мы этого не сделали. не видел каких-либо протоколов, подтверждающих это.

Моя цель здесь - выяснить: а) почему это происходит и б) что мы можем сделать, чтобы смягчить или обойти проблему.

Спасибо за глаза!