Re: Не понимаю в чем причина кода ответа 504 с ошибкой Connection timed out

[Maxim Dounin]

Hello!

On Thu, Jun 15, 2017 at 05:21:38PM +0300, Алексанр Платонов wrote:

> Добрый день.
> 
> У меня есть ~30 хостов в 3-х разных ДЦ. Nginx принимает нагрузку и
> распределяет её по алгоритму WRR на php-fpm пулы, расположенные на этих же
> хостах.
> 
> Периодически, примерно 1/5000 (ошибка к общему кол-ву запросов)  на
> случайном хосте получает ошибку:
> front14 2017/06/15 15:37:40 [error] 13063#13063: *2446289 upstream timed
> out (110: Connection timed out) while connecting to upstream, client:
> 217.69.135.0, server: site, request: "GET
> /files/images/1284_1284/58/b4/58b455be4b559395714059e5.jpg
> HTTP/1.0", upstream: "fastcgi://217.69.137.52:8081", host: "site"
> 
> после получения ошибки nginx проксирует запрос на другой сервер и там все
> отрабатывает нормально.
> 
> front14 217.69.135.0 - - [15/Jun/2017:15:37:41 +0300] "GET
> /files/images/1284_1284/58/b4/58b455be4b559395714059e5.jpg HTTP/1.0" 200
> 139517 "-" "okhttp/3.4.1" "-" request_time: 1.660 upstream_addr:
> 217.69.137.52:8081, 217.69.137.51:8081 upstream_response_time: 0.677, 0.981
> upstream_status: 504, 200 upstream_cache_status: - "tid:"
> 13063-1497530259.494-217.69.135.0-163-2446289
> 
> Меня волнует это так как увеличивается время ответа и всегда есть некий
> фоновый поток 504 ошибок. Подскажите, пожалуйста почему возникает таймаут и
> как его избежать?
> 
> Файл nginx-debug с одной проблемной сессией: https://uploadfiles.io/eokgp
> Файл конфигурации nginx: https://ufile.io/w8x56
> Список upstream: https://ufile.io/3tt84
> Cписок параметров fastcgi: https://ufile.io/gdzaa
> Sysctl: https://ufile.io/cdboz
> 
> Снимал несколько раз tcpdump и наблюдал следующую картину:
> 1) хост с nginx послылает FIN на бэкенд сразу после своего же ACK бэкенду
> через 13ms, не пересылая данные вообще.
> 2) хост с nginx посылает RST через 10 мкс после получения SYN, ACK от
> бэкенда и через ~ 780 мкс от своего SYN.
> 
> типовой ss -i
> ESTAB      0      0          217.69.134.124:40538        217.69.137.52:tproxy
> 
>      cubic wscale:7,7 rto:202 rtt:2.75/1.5 cwnd:10 bytes_acked:865
> segs_out:3 segs_in:2 send 42.1Mbps rcv_space:14600
> 
> Не понятно почему при настройке nginx fastcgi_connect_timeout 300ms; в логе
> вижу upstream_response_time: 0.677 секунды. Есть этому объяснение?

При connect-таймауте в 300 миллисекунд любой потерянный пакет 
будет приводить к таймауту.  А какой-то процент потерянных пакетов - это 
нормальное состояние любой сети, так что нет причин удивляться 
тому, что часть соединений при таких настройках таймаутится.

Кроме того, следует понимать, что время внутри nginx'а обновляется 
единожды за итерацию цикла обработки событий.  В результате если 
обработка какого-то события занимает существенное время и/или 
таких событий много, это может сказаться как на latency операций в 
целом, так и на точности работы отдельных таймаутов.  Поскольку 
300 миллисекунд - время достаточно малое, это может быть заметно, 
если сервер сильно нагружен и/или где-то блокируется.

В связи с вышеизложенным не могу не отметить, что в вашем конфиге 
видны следы стороннего модуля отправки статистики в graphite.  
Судя по коду[1], в tcp-режиме этот модуль блокирует рабочий процесс 
при отправке накопленной статистики на сервер.  Это, скажем мягко, 
малопригодное для production-использования решение, так что стоит 
начать с простого - убрать модуль совсем, и посмотреть на 
результат.

[1] https://github.com/mailru/graphite-nginx-module/blob/master/src/ngx_http_graphite_module.c#L2204

-- 
Maxim Dounin
http://nginx.org/