Я запускаю Apache 2.2, preform MPM, на Debian Squeeze с mod_php (PHP 5.3), слушаю несколько портов (с memcached, работающим на той же машине). За последние 6 недель или около того я сталкивался с ситуациями, когда все соединения Apache отключались / блокировались в больших группах. Перезапуск Apache решит проблему на время от нескольких часов до дней.
Приложения PHP, запущенные на сервере, включают пользовательский веб-интерфейс, ориентированный на пользователя, в дополнение к Backend REST API, работающему на отдельном порту на том же компьютере. Приложение веб-интерфейса выполняет от 1 до 3 последовательных запросов REST к Backend API через http://127.0.0.1:8888/ при загрузке большинства страниц. Эти ошибки тайм-аута сначала регистрируются в журнале ошибок PHP как ошибки тайм-аута клиента REST через 30 секунд. Соответствующие тайм-ауты также можно увидеть в журнале ошибок Apache. Они приходят пачками, когда время ожидания всех запросов истекает, затем пакет запросов обрабатывается (по-видимому) быстро и успешно, за которым следует еще один пакет тайм-аутов. Для временного окна в несколько минут 8-25 секунд будут не чем иным, как тайм-аутом, за которым, возможно, последует одна секунда обрабатываемых запросов, а затем еще 8-25 секунд тайм-аутов. Если «окно тайм-аута» перед «пакетом запросов» короче, то следующее за ним будет длиннее. Пока эта проблема присутствует, curl http://localhost/server-status или curl запрос к сценарию PHP в любом из приложений будет либо истекать по тайм-ауту и завершаться ошибкой, либо иногда возвращаться от 25 до 60 секунд. В течение этого периода процессор доступен, оперативная память доступна, ввод-вывод работает нормально (хотя это одна вещь, которую я не лучший в мониторинге), а количество сокетов в SYN_RECV состояние намного ниже, чем у системы somaxconn и Apache ListenBacklog (но я вижу сокеты, ожидающие в очереди).
Во время отладки и исследований я заметил много вещей, которые просто не имеют смысла. Во-первых, в моем выше curl http://localhost/server-status пример, curl подключается и отправляет данные успешно, но никогда не получает ответа. Даже по прошествии 45 с лишним минут Apache, похоже, не сбрасывает соединение или что-то еще, и curl просто зависает и ждет. Например:
~# curl -vv http://localhost/server-status
* About to connect() to localhost port 80 (#0)
* Trying 127.0.0.1... connected
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /server-status HTTP/1.1
> User-Agent: curl/7.21.0 (x86_64-pc-linux-gnu) libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.2.6
> Host: localhost
> Accept: */*
>
Если я перезапущу Apache, все вернется в норму.
Всего у машины 4 ГБ; 768M используется MemCache), 4 ядра ЦП, а размер резидентной памяти для каждого процесса Apache варьируется от 20 МБ до 30 МБ. MaxClients был установлен на 100, который, по моим расчетам и наблюдениям, выполняется в рамках ресурсных ограничений. Моя первая трудность заключалась в воспроизведении проблемы, поскольку я видел, как она действительно проявляется примерно 9 раз за 6 недель. Догадываясь, я опустил MaxClients к 10 (устранение ограничений ресурсов), чтобы увидеть, могу ли я вызвать проблему, и она успешно воспроизведена - сразу же начал появляться "прерывистый" шаблон тайм-аутов. Бэклог TCP заполняется примерно до 10% емкости, и попытка сделать запрос, как указано выше, никогда не возвращается (даже если пакеты запросов проходят и завершаются; но мои curl запросы, похоже, никогда не проходят через пачку). Timeout установлен на 500, KeepAliveTimeout установлен на 5. sys.fs.file-max/sys.fs.file-nr показывает использование <1%. nofile ulimit значительно превышает FD, используемую для каждого процесса. Чувствуя себя застрявшим и лишенным видимости, я начал straceв моих процессах Apache. После тщательного анализа ничего особо не выделялось, никаких ошибок, никаких утечек FD из того, что я мог сказать. Однако во время "периодов тайм-аута" я действительно вижу довольно много:
[17284] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
В кадете может быть полезно, вот пара «циклов» доработанных strace вывод во всех запущенных процессах:
ps auxw | grep sbin/apache | awk '{print"-p " $2}' | xargs strace -e poll,select,connect,recvfrom,sendto,flock
генерирует:
[17293] flock(46, LOCK_EX <unfinished ...>
[17292] flock(46, LOCK_EX <unfinished ...>
[17291] flock(46, LOCK_EX <unfinished ...>
[17290] flock(46, LOCK_EX <unfinished ...>
[17288] flock(46, LOCK_EX <unfinished ...>
[17285] flock(46, LOCK_EX <unfinished ...>
[17283] flock(46, LOCK_EX <unfinished ...>
[17276] select(0, NULL, NULL, NULL, {0, 618967} <unfinished ...>
[17287] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17287] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 964 <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17289] --- SIGCHLD (Child exited) @ 0 (0) ---
[17289] sendto(47, "\24\0...", 20, ...) = 20
[17289] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17289] poll([{fd=47, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17289] select(48, [47], [47], NULL, {1, 0}) = 1 (out [47], left {0, 999997})
[17289] sendto(47, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17289] select(48, [47], [], NULL, {1, 0}) = 1 (in [47], left {0, 999997})
[17289] recvfrom(47, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17289] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17289] poll([{fd=47, events=POLLOUT}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17289] sendto(47, "GET /<URL>"..., 390, MSG_NOSIGNAL, NULL, 0) = 390
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, [...] <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, [...] (Timeout)
[17287] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 963 <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, [...] (Timeout)
[17289] poll([{fd=47, [...] <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, [...] (Timeout)
[17284] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17287] <... poll resumed> ) = 0 (Timeout)
[17287] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17287] --- SIGCHLD (Child exited) @ 0 (0) ---
[17292] <... flock resumed> ) = 0
[17292] sendto(47, "\24\0...", 20, ...) = 20
[17292] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] poll([{fd=47, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17292] select(48, [47], [47], NULL, {1, 0}) = 1 (out [47], left {0, 999997})
[17292] sendto(47, "<MC>"..., 37, MSG_NOSIGNAL, NULL, 0) = 37
[17292] select(48, [47], [], NULL, {1, 0}) = 1 (in [47], left {0, 999997})
[17292] recvfrom(47, "<MC>"..., 32768, 0, NULL, NULL) = 22479
[17285] <... flock resumed> ) = 0
[17285] sendto(47, "\24\0...", 20, ...) = 20
[17285] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17285] poll([{fd=47, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17285] select(48, [47], [47], NULL, {1, 0}) = 1 (out [47], left {0, 999997})
[17285] sendto(47, "<MC>"..., 37, MSG_NOSIGNAL, NULL, 0) = 37
[17285] select(48, [47], [], NULL, {1, 0}) = 1 (in [47], left {0, 999997})
[17285] recvfrom(47, "<MC>"..., 32768, 0, NULL, NULL) = 22479
[17285] sendto(47, "\24\0...", 20, ...) = 20
[17285] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17285] poll([{fd=47, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17285] select(48, [47], [47], NULL, {1, 0}) = 1 (out [47], left {0, 999997})
[17285] sendto(47, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17285] select(48, [47], [], NULL, {1, 0}) = 1 (in [47], left {0, 999997})
[17285] recvfrom(47, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17287] poll([{fd=44, events=POLLIN}], 1, 5000 <unfinished ...>
[17292] poll([{fd=44, events=POLLIN}], 1, 5000 <unfinished ...>
[17287] <... poll resumed> ) = 1 ([{fd=44, revents=POLLIN}])
[17285] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17285] poll([{fd=47, events=POLLOUT}], 1, 1000) = 1 ([{fd=47, revents=POLLOUT}])
[17285] sendto(47, "GET /<URL>"..., 380, MSG_NOSIGNAL, NULL, 0) = 380
[17285] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17285] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17285] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17292] <... poll resumed> ) = 1 ([{fd=44, revents=POLLIN}])
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17292] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999996})
[17292] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17292] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17292] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17292] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17292] sendto(46, "<MC>"..., 37, MSG_NOSIGNAL, NULL, 0) = 37
[17292] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17292] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 22479
[17287] sendto(46, "\24\0...", 20, ...) = 20
[17287] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17287] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17287] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17287] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17287] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17287] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17292] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17287] sendto(46, "\24\0...", 20, ... <unfinished ...>
[17292] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
[17287] <... sendto resumed> ) = 20
[17292] <... sendto resumed> ) = 35
[17292] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17292] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17287] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17287] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17287] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17287] sendto(46, "<MC>"..., 37, MSG_NOSIGNAL, NULL, 0) = 37
[17287] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999996})
[17287] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 22479
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17292] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17292] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17292] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17292] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17292] flock(46, LOCK_EX <unfinished ...>
[17287] sendto(46, "\24\0...", 20, ...) = 20
[17287] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17287] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17287] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17287] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17287] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17287] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17287] sendto(46, "\24\0...", 20, ...) = 20
[17287] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17287] poll([{fd=46, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 1000) = 1 ([{fd=46, revents=POLLOUT}])
[17287] select(47, [46], [46], NULL, {1, 0}) = 1 (out [46], left {0, 999997})
[17287] sendto(46, "<MC>"..., 35, MSG_NOSIGNAL, NULL, 0) = 35
[17287] select(47, [46], [], NULL, {1, 0}) = 1 (in [46], left {0, 999997})
[17287] recvfrom(46, "<MC>"..., 32768, 0, NULL, NULL) = 7280
[17287] flock(46, LOCK_EX <unfinished ...>
[17289] <... poll resumed> ) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17289] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 1000 <unfinished ...>
[17276] <... select resumed> ) = 0 (Timeout)
[17276] select(0, NULL, NULL, NULL, {1, 0} <unfinished ...>
[17284] <... poll resumed> ) = 0 (Timeout)
[17284] poll([{fd=47, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
[17284] poll([{fd=47, [...] <unfinished ...>
...
Не уверен, что poll() таймауты не имеют к этому никакого отношения.
Чтобы далее сгенерировать шаблон трафика и указать на странную взаимосвязь с SIGCHLD уведомления, вот strace с просто connect(), recvfrom(). Я нажимал Enter несколько раз после того, как не видел выхода в течение 5 секунд (хотя большинство из них приходило последовательным всплеском (хотя иногда были пары секунд между GET /... и остальное)) для наглядности.
[17289] sendto(47, "GET /[BACKEND CALL]"..., 390, MSG_NOSIGNAL, NULL, 0) = 390
[17283] --- SIGCHLD (Child exited) @ 0 (0) ---
[17292] sendto(47, "\24\0...", 20, ...) = 20
[17292] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(47, "[MC]"..., 37, MSG_NOSIGNAL, NULL, 0) = 37
[17292] recvfrom(47, "[MC]"..., 32768, 0, NULL, NULL) = 22479
[17288] sendto(47, "\24\0...", 20, ...) = 20
[17288] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(47, "[MC]"..., 37, ...) = 37
[17288] recvfrom(47, "[MC]"..., ...) = 22479
[17288] sendto(47, "\24\0...", 20, ...) = 20
[17288] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(47, "[MC]"..., 35, ...) = 35
[17288] recvfrom(47, "[MC]"..., ...) = 7280
[17288] sendto(47, "\24\0...", 20, ...) = 20
[17288] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17288] sendto(47, "GET /[BACKEND CALL]"..., 380, ...) = 380
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(46, "[MC]"..., 35, ...) = 35
[17292] recvfrom(46, "[MC]"..., ...) = 7280
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(46, "[MC]"..., 37, ...) = 37
[17292] recvfrom(46, "[MC]"..., ...) = 22479
[17283] sendto(46, "\24\0...", 20, ...) = 20
[17283] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17283] sendto(46, "[MC]"..., 35, ...) = 35
[17283] recvfrom(46, "[MC]"..., ...) = 7280
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(46, "[MC]"..., 35, ...) = 35
[17292] recvfrom(46, "[MC]"..., ...) = 7280
[17283] sendto(46, "\24\0...", 20, ...) = 20
[17283] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17283] sendto(46, "[MC]"..., 37, ...) = 37
[17283] recvfrom(46, "[MC]"..., ...) = 22479
[17292] sendto(46, "\24\0...", 20, ...) = 20
[17292] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17292] sendto(46, "[MC]"..., 35, ...) = 35
[17292] recvfrom(46, "[MC]"..., ...) = 7280
[17283] sendto(46, "\24\0...", 20, ...) = 20
[17283] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17283] sendto(46, "[MC]"..., 35, ...) = 35
[17283] recvfrom(46, "[MC]"..., ...) = 7280
[17283] sendto(46, "\24\0...", 20, ...) = 20
[17283] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17283] sendto(46, "[MC]"..., 35, ...) = 35
[17283] recvfrom(46, "[MC]"..., ...) = 7280
<Long Wait>
[17284] --- SIGCHLD (Child exited) @ 0 (0) ---
[17284] sendto(46, "\24\0...", 20, ...) = 20
[17284] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(46, "[MC]"..., 35, ...) = 35
[17284] recvfrom(46, "[MC]"..., ...) = 7280
[17284] sendto(46, "\24\0...", 20, ...) = 20
[17284] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(46, "[MC]"..., 37, ...) = 37
[17284] recvfrom(46, "[MC]"..., ...) = 22479
[17284] sendto(46, "\24\0...", 20, ...) = 20
[17284] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(46, "[MC]"..., 35, ...) = 35
[17284] recvfrom(46, "[MC]"..., ...) = 7280
[17284] sendto(46, "\24\0...", 20, ...) = 20
[17284] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(46, "[MC]"..., 35, ...) = 35
[17284] recvfrom(46, "[MC]"..., ...) = 7280
[17284] sendto(47, "\24\0...", 20, ...) = 20
[17284] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(47, "[MC]"..., 37, ...) = 37
[17284] recvfrom(47, "[MC]"..., ...) = 22479
[17284] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17284] sendto(47, "POST /[BACKEND CALL]"..., 412, ...) = 412
<Long Wait>
[17289] --- SIGCHLD (Child exited) @ 0 (0) ---
[17293] sendto(47, "\24\0...", 20, ...) = 20
[17293] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17293] sendto(47, "[MC]"..., 37, ...) = 37
[17293] recvfrom(47, "[MC]"..., ...) = 22479
[17290] sendto(47, "\24\0...", 20, ...) = 20
[17290] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17290] sendto(47, "[MC]"..., 37, ...) = 37
[17290] recvfrom(47, "[MC]"..., ...) = 22479
[17290] sendto(47, "\24\0...", 20, ...) = 20
[17290] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17290] sendto(47, "[MC]"..., 35, ...) = 35
[17290] recvfrom(47, "[MC]"..., ...) = 7280
[17290] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17290] sendto(47, "POST /[BACKEND CALL]"..., 427, ...) = 427
[17289] sendto(46, "\24\0...", 20, ...) = 20
[17289] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17289] sendto(46, "[MC]"..., 35, ...) = 35
[17289] recvfrom(46, "[MC]"..., ...) = 7280
[17289] sendto(46, "\24\0...", 20, ...) = 20
[17289] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17289] sendto(46, "[MC]"..., 37, ...) = 37
[17289] recvfrom(46, "[MC]"..., ...) = 22479
[17289] sendto(46, "\24\0...", 20, ...) = 20
[17289] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17289] sendto(46, "[MC]"..., 35, ...) = 35
[17289] recvfrom(46, "[MC]"..., ...) = 7280
[17289] sendto(46, "\24\0...", 20, ...) = 20
[17289] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17289] sendto(46, "[MC]"..., 35, ...) = 35
[17289] recvfrom(46, "[MC]"..., ...) = 7280
[17293] sendto(46, "\24\0...", 20, ...) = 20
[17293] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17293] sendto(46, "[MC]"..., 35, ...) = 35
[17293] recvfrom(46, "[MC]"..., ...) = 7280
[17293] sendto(46, "\24\0...", 20, ...) = 20
[17293] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17293] sendto(46, "[MC]"..., 37, ...) = 37
[17293] recvfrom(46, "[MC]"..., ...) = 22479
[17293] sendto(46, "\24\0...", 20, ...) = 20
[17293] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17293] sendto(46, "[MC]"..., 35, ...) = 35
[17293] recvfrom(46, "[MC]"..., ...) = 7280
[17293] sendto(46, "\24\0...", 20, ...) = 20
[17293] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17293] sendto(46, "[MC]"..., 35, ...) = 35
[17293] recvfrom(46, "[MC]"..., ...) = 7280
<Long Wait>
[17288] --- SIGCHLD (Child exited) @ 0 (0) ---
[17291] sendto(47, "\24\0...", 20, ...) = 20
[17291] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17291] sendto(47, "[MC]"..., 37, ...) = 37
[17291] recvfrom(47, "[MC]"..., ...) = 22479
[17291] sendto(47, "\24\0...", 20, ...) = 20
[17291] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17291] sendto(47, "[MC]"..., 35, ...) = 35
[17291] recvfrom(47, "[MC]"..., ...) = 7280
[17291] sendto(47, "\24\0...", 20, ...) = 20
[17291] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17291] sendto(47, "GET /[BACKEND CALL]"..., 380, ...) = 380
[17288] sendto(46, "\24\0...", 20, ...) = 20
[17288] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(46, "[MC]"..., 35, ...) = 35
[17288] recvfrom(46, "[MC]"..., ...) = 7280
[17288] sendto(46, "\24\0...", 20, ...) = 20
[17288] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(46, "[MC]"..., 37, ...) = 37
[17288] recvfrom(46, "[MC]"..., ...) = 22479
[17288] sendto(46, "\24\0...", 20, ...) = 20
[17288] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(46, "[MC]"..., 35, ...) = 35
[17288] recvfrom(46, "[MC]"..., ...) = 7280
[17288] sendto(46, "\24\0...", 20, ...) = 20
[17288] connect(46, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17288] sendto(46, "[MC]"..., 35, ...) = 35
[17288] recvfrom(46, "[MC]"..., ...) = 7280
<Long Wait>
[17284] --- SIGCHLD (Child exited) @ 0 (0) ---
[17284] sendto(47, "\24\0...", 20, ...) = 20
[17284] connect(47, ...11211...127.0.0.1 = -1 EINPROGRESS (...)
[17284] sendto(47, "[MC]"..., 35, ...) = 35
[17284] recvfrom(47, "[MC]"..., ...) = 7280
[17284] connect(47, ...(8888)...("127.0.0.1")...) = -1 EINPROGRESS (...)
[17284] sendto(47, "GET /[BACKEND CALL]"..., 347, ...) = 347
<Long Wait>
...
Обратите внимание, что ни один из этих запросов не является «запросом веб-интерфейса». Некоторые вещи напрямую попадают в серверную часть, поэтому это не обязательно означает, что запрос внешнего интерфейса никогда не пройдет. я нашел эта почта что очень похоже на проблему, с которой я столкнулся, но решение (не выполнение HTTP-вызовов из запросов) на самом деле не применимо. При просмотре приведенного выше вывода в течение длительного периода времени я вижу только один запрос «Web UI» на каждые 100+ запросов «Backend», поэтому у меня не создается впечатления, что это какая-то тупиковая ситуация, ожидающая вызова backend. вернуться, но только с 10 MaxClients, возможно, есть как минимум 1 ожидающий (не уверен; не вижу /server-status когда возникает эта проблема).
Я довольно застрял на этом этапе; никогда раньше не видел ничего подобного. Вероятно, приведенной выше информации недостаточно, чтобы ответить на этот вопрос должным образом, поэтому, если кто-то может придумать какие-либо другие результаты или тесты, которые помогут в отладке этого, дайте мне знать, и я отредактирую. Любое руководство было бы очень признательно.