«Здравствуйте. Меня зовут Вячеслав, мне 22 года и я пхп программист. Я сижу на PHP с 18 лет.»… (копирайт не знаю чей, я не Вячеслав и мне давно не 22 года).
Да, у нас проект на PHP и мы столкнулись с тем, что на MySQL сервере стало появляться большое количество коннектов в состоянии Sleep.
А виноват в этом оказался код, работаюший с кроликом (RabbitMQ).
Ну а как связаны MySQL, RabbitMQ и закомментаренная строка вы узнаете код катом.
Архитектура нашей системы достаточно стандартная. Основная часть данных в MySQL. Имеется масштабируемый пул worker'ов на NodeJS. PHP процессы через RabbitMQ ставят задачи этим worker'ам и из того же кролика получает назад результаты.
В какой-то момент у нас стали возникать проблемы с тем, что PHP процессы (у наc Nginx + php-fpm) иногда не могут подключиться к MySQL. Есть проблема — нужно ее решать!
Стали смотреть на MySQL. Из аномального заметили, что show processlist показывает чрезмерно большое количество коннектов в состоянии sleep.
mysql> show processlist;
+----------+--------------+---------------------+-----------------+-------------+--------+
| Id | User | Host | db | Command | Time |
+----------+--------------+---------------------+-----------------+-------------+--------+
...............
| 16941988 | new_search | 172.16.10.214:59412 | parts_nm_new | Sleep | 19667 |
| 16941993 | new_search | 172.16.10.213:58562 | parts_nm_new | Sleep | 19666 |
...............
Это только часть вывода команды. Подобных процессов мы обнаружили более 100 штук и их количество со временем росло. Причем по Time видно, что в Sleep процессы висят очень давно.
Такого раньше не было и быть не должно.
Хорошо, тут мы видим IP PHP серверов (а PHP серверов у нас порядка 10 штук), с которых висели подозрительные коннекты.
Выбираем для исследований сервер 172.16.10.214 и идем смотреть, что там творится.
pm.max_requests у нас имеет не самое большое значение и по логике вещей, мы должны найти php-fpm процесс, который стартовал достаточно давно, т.к. в штатном режиме php-fpm процессы регулярно рестартуются мастер процессом.
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
................
nginx 6627 3.6 2.6 961232 103940 ? S 22:29 0:09 php-fpm: pool main_socket
nginx 8434 2.7 2.5 956224 99416 ? D 22:30 0:07 php-fpm: pool main_socket
nginx 8449 2.9 2.0 958124 79312 ? S 22:30 0:07 php-fpm: pool main_socket
nginx 10798 0.0 1.9 954268 75696 ? S 16:59 0:06 php-fpm: pool main_socket
nginx 11412 0.0 2.6 961384 104128 ? S 17:48 0:06 php-fpm: pool main_socket
nginx 12173 0.0 2.0 960452 79664 ? S 17:48 0:06 php-fpm: pool main_socket
nginx 13260 0.0 2.6 955920 102360 ? S 17:00 0:03 php-fpm: pool main_socket
nginx 13663 0.0 1.1 953040 44324 ? S 17:01 0:00 php-fpm: pool main_socket
root 23213 0.0 0.1 939640 7768 ? Ss 15:41 0:01 php-fpm: master process (/opt/php5/etc/php-fpm.main.conf)
................
И мы видим “залипший” процесс (на самом деле их несколько) по достаточно старому времени запуска (START). Например, процесс с PID 10798 висит уже несколько часов.
Нам конечно же интересно понять, чем он там занимается. Цепляемся к нему strace'ом и видим:
strace -p 10798
Process 10798 attached - interrupt to quit
recvfrom(10,
ну а дальше тишина. Процесс чего-то от кого-то ждет. Как по дескриптору 10 понять, с чем от связан (файл, сокет) я не знаю. Наверное как-то можно. Буду благодарен, если в комментах подскажете, как это сделать. В будущем пригодится.
Изучив еще несколько подозрительных процессов на других серверах было выявлено, что все они висят на recvfrom.
Копаем дальше. Смотрим, какие коннекты держит процесс с PID 10798:
netstat -ap|grep 10798
tcp 0 0 v-php-ws2:47736 mongodb01:27017 ESTABLISHED 10798/php-fpm
tcp 0 0 v-php-ws2:55686 memcached-vip:memcache ESTABLISHED 10798/php-fpm
tcp 0 0 v-php-ws2:59412 mysql-master:mysql ESTABLISHED 10798/php-fpm
tcp 0 0 v-php-ws2:54630 rabbitmq:amqp ESTABLISHED 10798/php-fpm
tcp 0 0 v-php-ws2:58901 mongodb02:27017 ESTABLISHED 10798/php-fpm
udp 0 0 *:43387 *:* 10798/php-fpm
unix 2 [ ] STREAM CONNECTED 20141894 10798/php-fpm /var/run/php-fpm-main.socket
Что мы видим. Коннект с MySQL сервером ( mysql-master:mysql ) — это мы и так знаем. Именно этот коннект в состоянии Sleep мы видели на MySQL сервере.
Коннект к memcache сервером. Там у нас хранятся сессии пользователей.
Коннект с MongoDB — там у нас часть закешированных данных лежит. А два коннекта, т.к. кластер MongoDB из трех серверов, один из которых арбитр.
И коннект к кролику (RabbitMQ).
Исходя из логики приложения к кролику коннект происходит позже всего. И если бы мы зависли на другом соединении, то скорее всего до кролика дело бы не дошло. Поэтому основным подозреваемым стал коннект именно к кролику.
Идем на RabbitMQ и ищем подозреваемый коннект (54630 — это исходящий порт коннекта к кролику проблемного php-fpm, см. предыдущий вывод netstat):
netstat -anp|grep 54630
tcp 0 0 ::ffff:172.16.10.218:5672 ::ffff:172.16.10.214:54630 ESTABLISHED 2364/beam
Что-то умнее, чем пробовать этот коннект убить с помощью killcx.sourceforge.net в голову не приходит, т.к. tcpdump говорит, что данные в этом коннекте не ходят:
killcx 172.16.10.214:54630
killcx v1.0.3 - (c)2009-2011 Jerome Bruandet - http://killcx.sourceforge.net/
[PARENT] checking connection with [172.16.10.214:54630]
[PARENT] found connection with [172.16.10.218:5672] (ESTABLISHED)
[PARENT] forking child
[CHILD] interface not defined, will use [eth1]
[CHILD] setting up filter to sniff ACK on [eth1] for 5 seconds
[PARENT] sending spoofed SYN to [172.16.10.218:5672] with bogus SeqNum
[CHILD] hooked ACK from [172.16.10.218:5672]
[CHILD] found AckNum [2073273429] and SeqNum [1158333446]
[CHILD] sending spoofed RST to [172.16.10.218:5672] with SeqNum [2073273429]
[CHILD] sending RST to remote host as well with SeqNum [1158333446]
[CHILD] all done, sending USR1 signal to parent [8658] and exiting
[PARENT] received child signal, checking results...
=> success : connection has been closed !
И тут случилось чудо, зависший php-fpm (по strace стало видно) весело побежал дальше работать и зависший коннект с MySQL сервером исчез!
Результат расследований выявил проблемный участок — почему-то PHP чего-то долго ждет (он же в recvfrom системной вызове висит) от кролика.
У нас логика приложения такая, что если от кролика нет ответа более 5 секунд, то ждать уже нет смысла. А тут зависания навечно.
Пошли смотреть в код и вот оно!!! Закомментированная строка, которая случайно ушла в продакшен:
$cnn = new \AMQPConnection($conn);
// $cnn->setReadTimeout(5);
Теперь мы знаем, как нам починиться. Но почему NodeJS иногда не отправляют в кролик результаты расчетов за 5 секунд? Нужно масштабироваться? Нет, там еще запас прочности гигантский.
И я знаю, почему NodeJS иногда не присылает результаты, но не знаю, из-за чего это происходит.
Если посмотреть логи RabbitMQ, то у нас там есть ошибки, которые мы давно не можем понять, из-за чего они происходят. Вот эти ошибки:
=ERROR REPORT==== 26-Nov-2015::06:03:11 ===
Error on AMQP connection <0.16535.3527> (172.16.10.95:44482 -> 172.16.10.218:5672, vhost: '/', user: 'php', state: running), channel 1:
{amqp_error,frame_error,
"type 1, first 16 octets = <<0,60,0,40,0,0,28,80,97,114,116,75,111,109,77,97>>: {invalid_frame_end_marker,\n 2}",
none}
=ERROR REPORT==== 26-Nov-2015::06:20:12 ===
Error on AMQP connection <0.18878.3534> (172.16.10.95:44683 -> 172.16.10.218:5672, vhost: '/', user: 'php', state: running), channel 512:
{amqp_error,frame_error,
"type 206, all octets = <<>>: {frame_too_large,16777216,131064}",
none}
Вот эти два типа ошибок иногда, примерно пару раз в час возникают при работе NodeJS c RabbitMQ. На NodeJS возникает Exception и результат в очередь не записывается. Ну и соответственно PHP его не дожидается. PHP ждет 5 сек и идет дальше. Мы можем себе позволить потерять ответ (это не банковские транзакции). Но мы пытаемся понять природу этих ошибок. К сожалению, пока безуспешно.
Мораль: зачем я это все написал?
Это не первый случай, когда мне приходится опускаться до уровня strace. И мне иногда кажется, что могут быть более высокоуровневые инструменты выявления подобных проблем. При тестировании проблема не воспроизводится. Ловится она только на продакшене. Как бы вы поступили в моей ситуации?
Ну и вторая причина. Вдруг кто-то уже сталкивался с подобной проблемой RabbitMQ (см. ошибки выше)? Если вы знаете природу этих ошибок, то дайте знать. Можно в личку.
Комментарии (25)
Labutin
27.11.2015 00:55По поводу данных, которые от NodeJS к RabbitMQ идут — мы думали, что дело в них. Но проблема возникает какими-то набегами. Корреляцию с данными не обнаружили.
А пул воркеров вы имеете в виду php-fpm? Как я написал, их у нас около 10 штук. На каждой ноде стоит максимальное кол-во php-fpm 50. Итого коннектов может максимум дорастать до 500, что для MySQL не так уж и много.
Отдельная тема, почему у нас начали возникать проблемы с коннектами к MySQL еще до того, как мы дошли до порога 600:
mysql> show variables like '%max_connections%'; +-----------------------+-------+ | Variable_name | Value | +-----------------------+-------+ | extra_max_connections | 1 | | max_connections | 600 | +-----------------------+-------+
Если выясню, может будет статья о другом расследовании.xytop
27.11.2015 13:55У нас в rabbitmq складываются только ключи, а сами данные лежат в redis, удаляются после обработки задачи. Нам кажется что так понадежнее, хотя кто-то может сказать что добавили себе вторую точку отказа) Зато есть возможность восстановить очередь в случае чего.
m00t
27.11.2015 02:01gdb!
m00t
27.11.2015 02:04+1Там у меня старенькая статья, можете в профиле посмотреть. Тоже была похожая проблема — только на продакшене и через несколько дней все зависало. gdb позволяет увидеть php стектрейс где висим ну и соответственно понять почему. Я понимаю, что использовать gdb это вообще жесть, но ведь сработало =)
Labutin
27.11.2015 07:22Действительно, в gdb же можно посмотреть стектрейс. Нужно будет освоить на будущее.
ValdikSS
04.12.2015 12:49+1Я понимаю, что использовать gdb это вообще жесть
Не убирайте дебаг-символы, а лучше вообще скомпилируйте из исходников и не удаляйте исходники, в таком случае, gdb вам даже строчку в исходнике покажет, которую он сейчас исполняет.m00t
04.12.2015 19:39Да, я так и делал, компилил с -g вроде (--enable-debug или как там), не помню точно уже.
m00t
27.11.2015 02:06+6Вообще, конечно, это круто. Часто вижу девелоперов, которые сталкиваясь с такой сложной проблемой говорят «а фиг его знает» и вставляют подпорки типа ежечасного рестарта воркеров вместо того чтобы разобраться в сути проблемы.
CSharpRU
27.11.2015 08:21+1В вашей компании недостаточно code review.
Labutin
27.11.2015 08:28+1Совет конечно правильный и точно в цель.
Но у всех на слуху одно мобильное приложение одной крупной компании, которое ушло в продакшн с дебаг кодом, что приводило к тому, что место на смартфонах быстро заканчивалось.
Все мы люди и допускаем ошибки, торопимся. И иногда эти ошибки нужно находить и устранять.CSharpRU
27.11.2015 08:32Да, ошибаются все. Я вас не обвиняю, просто концентрирую ваше внимание на данном вопросе :)
garex
27.11.2015 08:49По обоим ошибкам очень похоже на какие-то лимиты в RMQ. См. первые ссылки на SO по ним. Ваш кэп.
redmanmale
27.11.2015 09:57Читается как остросюжетный детектив!
jrip
27.11.2015 11:33-1Да какой тут детектив? Небось достаточно было по логу ближайших комитов, либо при сравнении раннней версии кода, когда таких проблем не было, увидеть что кто-то зачемто закомментировал строчку.
DenimTornado
27.11.2015 11:48«В какой-то момент» вот именно тут надо было первым делом бежать в лог гита (или что у вас там) и смотреть крайние коммиты. И до стектрейса не дошло.
jrip
27.11.2015 12:26-1Да на самом деле, все проще — эти парни небось даже code review не делают. Да вот даже то самое банальное, перед комитом тупо посмотреть diff того чего комитишь.
roman_kashitsyn
27.11.2015 13:00-1эти парни небось даже code review не делают
Хорошо ещё если VCS используется — про коммиты в статье ни слова:
Закомментированная строка, которая случайно ушла в продакшен:
Как именно она туда ушла — ни слова :)Labutin
27.11.2015 13:46+4Троль детектед :)
Конечно же мы на сервер носим код на дискетках, а git или svn — это для нас какие-то странные три буквы, которых мы боимся!
Знаете как прикольно с дискеткаки бегать между десятками серверов и релизить одновременно!
Командир поднимает руку и командует — релиз!!! И разработчики одновременно на все сервера копируют новый код. Разве кто-то сейчас делает по-другому?jrip
27.11.2015 16:33Ну чутка он вас конечно тролит, но в целом он прав)
При прочтении только названия статьи — сразу вопрос каким таким образом она вообще туда ушла.
Ну и собственно мораль у вас не правильная получается.Labutin
27.11.2015 22:52+1Честно говоря, не хотел продолжать эту ветку в комментариях. Но под вечер решил ответить.
1. Согласен, что лучше вообще не допускать ошибок в написании кода.
2. Согласен, что лучше устроить такой процесс code review, что просочившись через первый пункт ошибка будет выловлена другими членами команды.
Но я не видел еще ни одного «Гугла», «Яндекса», «Яблока» и т.п. которые бы даже при таком подходе в продакшн не отправляли бы код с ошибкой. И никакой CI тоже не помогает. Все это конечно устремляет вероятность ошибки к нулю, то пока код пишут люди, а не роботы — такого не будет.
А когда ошибка проявляется не сама по себе, а в следствии стечения обстоятельств других подсистем (в моем случае кролика и ноды), то и проявляться она начинает далеко не сразу.
Некоторые комментаторы сделали предположения, что коммит с закомментаренной строкой совпал с началом проблем. Но я про это даже близко не упоминал.
Я не спорю, можно было просмотреть логи коммитов нескольких месяцев назад и найти проблему без дебага. Но IMHO это заняло бы «чуток» больше времени.
И если непонятно, как строка ушла в продакшн, то лично я бы уточнил бы этот вопрос, а не сразу стал бы домысливать страшные картинки и делать тролеподобные выводы. Так можно напридумывать фантазий которые к реальной жизни не имеют никакого отношения.
justmara
27.11.2015 13:57"мы заметили, что в node.js временами залипают коннекты в ..."
свежо, ага. у нас точно также непредсказуемо залипали http-коннекты. и просто чистые tcp-stream. задолбались ловить.
xytop
А вы логируете, то что скидывается из node в rabbitmq? Возможно проблема в данных. Ну или в драйвере.
Что у вас за пулл такой, который жрёт подключения бесконтрольно? Если в пуле 100 воркеров то и подключений должно быть 100 и не больше.