2013/11/20 Eugene Berdnikov <b...@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 или ядро, куда двигаться дальше?
