Долгий путь низкоуровневого дебага, чтобы найти закомментаренную строку кода, случайно ушедшую в продакшн
«Здравствуйте. Меня зовут Вячеслав, мне 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 (см. ошибки выше)? Если вы знаете природу этих ошибок, то дайте знать. Можно в личку.
