Re: poll() timeout в PHP-FPM при получении запросов от Nginx

2013/11/20 Eugene Berdnikov <bd4@protva.ru>

On Wed, Nov 20, 2013 at 12:03:50PM +0300, Bogdan wrote:
> > On Tue, Nov 19, 2013 at 11:58:33PM +0300, Bogdan wrote:
> > > Т.е. непонятно по какой причине poll() зависает на 5 секунд блокируя
> > работу
> > > интерпретатора.
> >
> > Скорее всего, по той причине, что никаких данных по сети не приходит.
>
> Не совсем тут понятно, что значит "никаких данных по сети не приходит" -
> т.е. удалённая сторона, в данном случае nginx, установила tcp-соединение,
> но данных в него не послала?

Может быть и так, но возможно данные посылались и потерялись где-то
по пути... Нужно не фантазировать а опираться на факт, что poll() вышел
на таймаут, значит, скорее всего на хосте-приёмнике данных не было.
И самый быстрый способ проверить это -- посмотреть дамп трафика.
После чего уже понятно, ядро виновато или локальная сеть.

Сегодня проблема воспроизвела на другом сервере, где nginx (1.2.1-2.2wheezy1) и php 5.4 на Debian 7, расположены вместе и коннект проходит сугубо через локалхост.

Выглядело это следующим образом:

20:43:09.699398 write(19, "\1\6\0\1\3\324\4\0X-Powered-By: PHP/5.4.4-14+deb7u5\r\nLast-Modified: Wed, 20 Nov 2013 16:43:09 +0000 GMT\r\nPragma: no-cache\r\nCon
tent-type: text/_javascript_\r\nExpires: Wed, 20 Nov 2013 16:43:09 +0000\r\nCache-Control: must-revalidate\r\nP3P: policyref=\"/w3c/p3p.xml\", CP=\"UN"..., 1008)
= 1008
20:43:09.699470 shutdown(19, 1 /* send */) = -1 ENOTCONN (Transport endpoint is not connected)
20:43:09.699504 recvfrom(19, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
20:43:09.699536 recvfrom(19, "", 8, 0, NULL, NULL) = 0
20:43:09.699561 close(19)               = 0
20:43:09.699682 setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
20:43:09.699714 accept(0, {sa_family=AF_INET, sin_port=htons(7837), sin_addr=inet_addr("192.168.1.2")}, [16]) = 19
20:43:09.699750 time(NULL)              = 1384965789
20:43:09.699775 times({tms_utime=1902, tms_stime=373, tms_cutime=0, tms_cstime=0}) = 2323052248
20:43:09.699802 poll([{fd=19, events=POLLIN}], 1, 5000) = 0 (Timeout)
20:43:14.705014 close(19)               = 0
20:43:14.705281 accept(0, {sa_family=AF_INET, sin_port=htons(3676), sin_addr=inet_addr("192.168.1.2")}, [16]) = 19
20:43:14.705435 time(NULL)              = 1384965794
20:43:14.705583 times({tms_utime=1902, tms_stime=373, tms_cutime=0, tms_cstime=0}) = 2323052748
20:43:14.705706 poll([{fd=19, events=POLLIN}], 1, 5000) = 0 (Timeout)
20:43:19.707391 close(19)               = 0
20:43:19.707519 accept(0, {sa_family=AF_INET, sin_port=htons(56862), sin_addr=inet_addr("192.168.1.2")}, [16]) = 19
20:43:19.707558 time(NULL)              = 1384965799
20:43:19.707582 times({tms_utime=1902, tms_stime=373, tms_cutime=0, tms_cstime=0}) = 2323053249
20:43:19.707607 poll([{fd=19, events=POLLIN}], 1, 5000) = 0 (Timeout)
20:43:24.711363 close(19)               = 0
20:43:24.711482 accept(0, {sa_family=AF_INET, sin_port=htons(40505), sin_addr=inet_addr("192.168.1.2")}, [16]) = 19
20:43:24.711524 time(NULL)              = 1384965804
20:43:24.711548 times({tms_utime=1902, tms_stime=373, tms_cutime=0, tms_cstime=0}) = 2323053749
20:43:24.711575 poll([{fd=19, events=POLLIN}], 1, 5000) = 1 ([{fd=19, revents=POLLIN}])
20:43:24.711608 read(19, "\1\1\0\1\0\10\0\0", 8) = 8
20:43:24.711638 read(19, "\0\1\0\0\0\0\0\0", 8) = 8
20:43:24.711670 read(19, "\1\4\0\1\5\36\2\0", 8) = 8
20:43:24.711698 read(19, "\f\200\0\0\352QUERY_STRING......

Т.е. после "успешного" запроса - несколько подряд попыток почитать что-нибудь из соединения, последняя оказывается успешной.

Из не нормального: количество соединений в состоянии SYN_SENT на порт PHP-FPM было более 1000 постоянно, SYN_RECV - чуть меньше.

После растарта php-fpm на этот раз всё самой собой "прошло", в netstat соединений на порт PHP нет. К сожалению ребут от этой беды спасает далеко не всегда.

Но по крайней мере, раз всё воспроизводится в пределах одного сервера - проблему интерконнекта наверное пока можно перестать рассматривать.

Дамп трафика в этот момент у меня получился без таймингов, tcp.analysis.retransmission показал два десятка пакетов - повторная передача [PSH, ACK] от nginx к PHP, всего в дампе ~50k пакетов.

И кого тут подозревать? PHP или ядро, куда двигаться дальше?