Плохая «Весна» или как причины задержек искали
Мы привыкли видеть истории проектов с миллионами клиентов и целым парком серверов, но разные интересные и курьезные ситуации могут встречаются и на относительно небольших проектах. Одна из них произошла недавно. Однажды работающий нормально сервер вдруг начал случайным образом тормозить…
Начну с небольшой предыстории. Часто достаются проекты, которые сменили много разработчиков, не всегда знающих что они делали или не задумывающих о том что делали до них. Не всегда возможно или тем более оправданно причесывать это все прямо сейчас, и приходится быстро исправлять проблемы, не взирая на общее желание выкинуть все это в трубу.
На одном таком проекте произошло странное. Приблизительно в тоже время, как были внесены небольшие исправлений по функционалу, неизвестно откуда стали возникать странные подтормаживания на генерацию страницы, чуть ли не по минуте. (виноват не тот кто все испортил, а тот кто последним трогал :) )
Расследование началось
Понимая что эти исправления не могут внести такого, начали копать. Первая мысль «это какой то странный timeout, наверное куда то удаленно стучимся». Надо было цепляться за эту идею и не отпускать её, но об этом чуть позже. Сайт был на битриксе, достаточно сложный и в нем было много разных агентов. Почти все их них отрабатывали по крону. Но мало ли что. Уж больно плавающими были подтормаживания, у разных пользователей и раз в несколько последовательных посещений (еще один тревожный звоночек, на который никто не обратил внимания).
Профилировщик битрикса показывал что дело в PHP коде ядра пролога. (как раз там иногда могут запускаться агенты). Иногда правда показывалось что проблема перемещается в код шаблона. Но так как в большинстве случаев был пролог решили начать с него. (очередная ошибка, которая могла сэкономить немного бесценного времени)
Начали копать последовательно.
- Шаг первый. Сначала откатили изменения внесенные, проблема не пропала. Вздохнули спокойно, все же не мы.
- Шаг второй. Добавили в механизм вызова агентов логирование времени работы. Никакой корреляции с подтормаживаниями, все цифры на уровне миллисекунд.
Надо бы значит замерить различные части ядра. (Вот тут бы вцепиться за дельную мысль, что зачем эти ручные замеры кода, надо бы поставить на боевой сервер XHProf и посмотреть, но было решено что и так найдется). Кусок ядра обфусцирован. Немного ловкости рук, и основные места становятся понятными, код разбит на куски, и можно проводить замеры отдельных его частей.
Область поиска сужается и вот мы находим нашего подозреваемого. Как так session_start() ???
Тучи сгущаются
Смотрим, сессии в файлах, файлы на SSD, сессий кот наплакал. Должно отрабатывать мгновенно. И вот здесь мы свернули с верного пути. Отправившись окольными путями. Мысли то логичные. Если сессия долго стартует, значит возможно проблемы с IO, на эту же идею работали задержки в шаблонах. Долго подключались файлы. htop/iotop и прочая братия показывает что проблем с вводом выводом нет. Папки с файлами летят туда сюда без каких то задержек. В логах рейда ошибок нет, прошивки у ssd последние. SSD производства Intel'а. То есть случай с Samsung упоминаемый на хабре тут никаким боком.
Пробуем перенести сессии на ram disk, безрезультатно. Проблема повторяется все чаще. Перезапуск процессов не помогает. Планируем на ночь перезагрузку физического сервера, чтобы исключить возможные проблемы, которые могли накопиться за год uptime'а, заодно встанут все обновления ядра.
Перезапуск не помог. В логах nginx встречаются странные надписи вида:
*38600646 an upstream response is buffered to a temporary file /var/cache/nginx/proxy_temp/7/29/0000006297 while reading upstream
-совпадающие по времени с известными подтормаживания. Похоже проблема гораздо более распространенна чем казалось. Подумав приходим к мысли что все логично, если апач по какой то причине ждет ожидания сессии и не виснет при этом, то он должен как то говорить nginx'у что все нормально, и надо подождать, значит вероятно шлет пустые пакеты, которые nginx кладет в буфер. Отставляем это в сторону и идем дальше.
Обновляем сервисы. apache/php/nginx обновлены. Проблема все еще есть. Свободной памяти на сервере под 25%, крутятся настройки swap'а чтобы избежать каких-нибудь гипотетических проблем с перекидыванием процессов апач на диск. Вполне ожидаемо никаких результатов.
Переносим на memcached хранение сессий. Пробуем найти решение проблемы на stackoverflow. (Уходим все дальше от корня проблемы, параллельно подкручивая настройки софта и системы). Переносим кэш частично в memcache частично на ram диск.
Как можно догадаться толку никакого.
Я должен погрузиться глубже
Достаем тяжелую артиллерию.
В очередной раз пытаемся поймать процесс с помощью команды — ps -e -o pid,comm,wchan=WIDE-WCHAN-COLUMN | grep httpd
Похоже это он — poll_schedule_timeout. Цепляемся с помощью strace.
Долгое ожидание —
restart_syscall(<... resuming interrupted call ...>)
После чего процесс оживает. Как и страница в браузере.
Видим работу с сокетами.
getsockopt(32, SOL_SOCKET, SO_ERROR, [110], [4]) = 0
fcntl(32, F_SETFL, O_RDWR) = 0
close(32) = 0
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 32
fcntl(32, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(32, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(32, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("87.250.250.85")}, 16) = -1 EINPROGRESS (Operation
now in progress)
Вспоминаются изначальные мысли о timeout'ах.
Похоже нашли виновника. Находим по strace куда мы стучались
sendto(32, "\0\264\1\0\0\1\0\0\0\0\0\0\5vesna\6yandex\2ru\0\0\1\0"..., 33, MSG_NOSIGNAL, NULL, 0) = 33
И закрываем vesna.yandex.ru. (Какая такая vesna.yandex.ru откуда она взялась то? Я понимаю какой нибудь doorway или что то подобное, но это? )
Проблемы вдруг пропадают. Отключаем memcache и ram диск, все нормально. Значит дело именно в этом.
Возвращаемся в логи strace и ищем там причину
lstat("/home/bitrix/ext_www/XXX/bitrix/modules/defa.tools/include.php", {st_mode=S_IFREG|0775, st_size=11
43, ...}) = 0
lstat("/home/bitrix/ext_www/XXX/bitrix/modules/defa.tools", {st_mode=S_IFDIR|0775, st_size=4096, ...}) =
0
lstat("/home/bitrix/ext_www/XXX/bitrix/modules/defa.tools/classes/general/ibprop_elemcompleter.php", {st_
mode=S_IFREG|0775, st_size=15267, ...}) = 0
Defa.Tools? А при чем тут defa.tools. профилирование же явно показывало на session_start().
Свет во тьме
Лезем в код. Видим получение архива с vesna.yandex.ru для автогенерирование каких то текстов. (функционал, который никто не использовал, да собственно как и сам модуль. его поставил кто-то из предыдущих разработчиков).
Начинает вырисовываться понимание того что вероятно из-за частого обращения либо еще по каким причинам, yandex время от времени отдает этот файл с задержкой либо вообще не отдает и поэтому мы стали натыкаться на эту проблему. (почему нельзя класть получаемый с яндекса файл в кэш на сервере, и время от времени обновлять, а не хранить в экземпляре класса и постоянно его запрашивать — это вопрос к разработчикам defa.tools)
Но почему он у нам вызывается, а главный вопрос причем тут session_start(). Продолжаем копать. И находим навешанный обработчик (напоминаем, достаточно сложный проект, который писала куча народу, переходящий от разработчика к разработчику, множество обработчиков в разных файлов иногда без какой то системы) на сохранение свойства.
Находим не правильно прописанный фильтр. Проблема тормозов наконец то найдена.
Разгадка
Теперь же вернемся к главной мистике, причем тут session_start. На всех страницах для авторизованных пользователей (в виду тематики и идеи сайта большинство пользователей авторизовано) присутствует вызов скрипта проверки обновлений ajax'ом. (websocket'ы? нет не слышал). Браузер отделяет зерна от плевел, поэтому позволяет открывать новую вкладку в момент выполнения ajax-запроса. Так как сессия там начата, но еще не законченна, session_start послушно ждет когда же ему дадут начать. И это никак не связано с io и прочим шаманством.
Какие же можно сделать выводы в итоге:
- Наследие старого кода всегда подкрадывается незаметно, и больно бъет по голове.
- Доверяйте своей интуиции. (Мысль об обращение к внешнему ресурсу оказалась верной. А шаманства с установкой и настрйкой XHProf позволили бы заметить что есть другие длительные задержки. И соответственно быстрее понять суть проблемы.)
- Выкатывайте тяжелую артиллерию пораньше.
- Вероятней всего проблема гораздо проще чем кажется.
