Перевод поста Стивена Вольфрама (Stephen Wolfram) «Scientific Bug Hunting in the Cloud: An Unexpected CEO Adventure».
Выражаю огромную благодарность Кириллу Гузенко за помощь в переводе.

Wolfram Cloud должен быть совершенным

Wolfram Cloud в самом скором времени выйдет из стадии бета-тестирования, в данный момент я трачу очень много времени на то, чтобы сделать эту систему как можно лучше (и, стоит заметить, получается действительно здорово!). В основном я занимаюсь высокоуровневыми функциями и стратегией. Но мне нравится контролировать процесс на всех уровнях, ведь, как CEO, я полностью отвечаю за все, что происходит в моей компании. И вот в начале марта я оказался погруженным в то, о чём никак не мог догадываться ранее.

Собственно, вот о чем речь. Как серьезная производственная система, которую многие люди будут использовать в том числе и для бизнеса, Wolfram Cloud должен работать как можно быстрее. Показатели говорили о том, что скорость достаточно хороша, но чисто субъективно чувствовалось, что что-то не так. Иногда всё было действительно быстро, но иногда казалось, что все работает слишком медленно.

В нашей команде есть отличные программисты, однако шли месяцы, и какие-бы то ни было изменений не ощущалось. А тем временем мы успели выпустить Wolfram Data Drop (см. статью на Хабрахабре «Wolfram Data Drop — новый сервис Wolfram Research»). Так что я подумал, почему бы мне самому не провести несколько тестов, возможно, и собрать немного информации в наш новый Wolfram Data Drop?

Существенное преимущество Wolfram Language заключается в том, насколько он хорош для занятых людей: даже если у Вас есть время только чтобы напечатать всего несколько строк кода (см. статью на Хабрахабре "Компания Wolfram Research открыла сервис Tweet-a-Program: интересных программ на языке Wolfram Language, длина которых не превышает 140 символов"), Вы сможете получить что-то действительно полезное. И, в данном случае, мне достаточно было просмотреть три строчки кода, чтобы найти проблему.

Сперва я развернул web API для простой программы на Wolfram Language в Wolfram Cloud:



Затем я вызывал API 50 раз подряд, каждый раз замеряя, сколько времени длился вызов (% представляет собой предыдущий вычисленный результат):



После этого я построил последовательность вызовов во времени:



И тут же получил нечто, что не укладывалось в голове. Иногда вызов занимал 220 мс или что-то вроде того, но дважды обнаружилась задержка в 900 мс. Но самое безумное было то, что сигнал, похоже, квантуется!

Я построил гистограмму:



И, конечно же, было несколько быстрых вызовов, которые расположились слева, довольно медленные вызовы посередине, а самые медленные – справа. Это было странно!

Я подумал, а всегда ли так происходит. Так что я создал плановую задачу — производить вызов API каждые несколько минут, а затем отправлять данные в Wolfram Data Drop. А когда на утро я вернулся, вот что я увидел:



Ещё более странная картина! Откуда тут появилась крупномасштабная структура? Я мог бы ещё понять, к примеру, что тот или иной узел в кластере постепенно замедляется, но почему он тогда медленно восстанавливается?

Первая моя мысль была, что я столкнулся с проблемами с сетью, учитывая, что я находился от облачного сервера на расстоянии более тысячи миль. Затем я взглянул на пинг. Но кроме парочки странных пиков (эй, это же интернет!), всё было весьма стабильно.

Что-то не так внутри серверов

Хорошо, должно быть, это какая-то проблема с самими серверами. Wolfram Cloud содержит в себе много разных технологий, но в основном это все же чистый код на Wolfram Language, который легко тестируется. Но за слоем самого языка присутствует современная серверная инфраструктура. Многое из неё есть практически тоже самое, что использовалась в Wolfram|Alpha последние полтора десятка лет для вывода миллиардов результатов, и что используется в webMathematica последние десять лет. Но, будучи несколько более требовательной вычислительной системой, Wolfram Cloud устроен немного по-другому.

И первой моей догадкой было то, что разные настройки могут быть причиной того, что что-то идёт не так в слое веб сервера. В конце концов, Я надеюсь, вся инфраструктура сверху до низу будет написана на чистом Wolfram Language, однако сейчас нам приходится использовать веб сервер TomCat, который работает на Java. И первое, что я подумал, что подобные замедления могут быть вызваны сборщиком мусора Java. Анализ показал, что сборка мусора, инициированная Tomcat, действительно вызывала некоторые замедления, однако они были незначительными и измерялись в единицах миллисекунд, а не в сотнях. Так что это не могло быть объяснением.

Я был весьма сосредоточен на поиске проблемы. Мне уже очень давно не приходилось так глубоко копать в поиске проблем и ошибок. Ощущалось, как будто я занимаюсь экспериментальной наукой. И, как принято в экспериментальной науке, важно как можно более упростить объект исследования. Таким образом, я вырезал большую часть элементов сети, управляя “облаком из облака” (вызывая API с того же самого кластера). Затем я удалил балансировщик нагрузки, который отправляет запросы к конкретным узлам кластера, заблокировав мои запросы к конкретному узлу (что, кстати, сторонние пользователи не смогут сделать, если у них нет частного облака). Однако задержка всё ещё оставалась.

После этого я начал собирать более подробные данные. Первым моим шагом было создание API, который возвращал абсолютное время начала и конца выполнения кода Wolfram Language и сравнивал его с абсолютным временем в интерфейсе API. И вот что я увидел:



Голубая линия означает время до того, как код Wolfram Language запустился; золотая линия – после. Я собирал эти данные в период, когда система в целом работала довольно плохо. Я увидел серьезные замедления в периоде до инициализации, и лишь небольшие единичные замедления в периоде после.

И снова – это было очень странно. Не было похоже, что замедления были связаны конкретно с периодом «до» или «после». Наоборот, как будто-бы что-то случайное извне системы выбивало её.

Меня смущал тот факт, что каждый узел кластера в общем случае содержит восемь ядер, и каждое ядро работает со своим экземпляром Wolfram Engine. Движок сбалансирован и работает стабильно, и каждый его экземпляр может работать много часов или даже дней без перезагрузки. И я подумал — а что если некоторые экземпляры содержат какие-то ошибки? После чего решил соорудить API, который бы отслеживал ID и время работы процессов, а затем, к примеру, строил бы зависимость общего времени процесса от времени исполнения компонентов API:



И действительно, стали проглядываться тенденции у новых процессов по более быстрому вызову API, но (особенно отмечая группировку точек у нуля на оси x), эффект оказался несущественным.

Чем питается CPU?

Я начал задумываться о других сервисах Wolfram Cloud, запущенных на одной той же машине. Казалось бы, не имеет смысла, что они могут при этом приводить к тем самым квантованным замедлениям, однако для упрощения системы я хотел избавиться и от них. В первую очередь мы изолировали узел на производственном кластере. Затем я принялся настраивать свой частный Wolfram Private Cloud. Но замедления всё оставались. Хотя, в разное время и на разных машинах их характеристики, казалось, несколько различались.

В частном облаке я мог просто войти в сырой Linux и начать осматриваться. Первое, что я сделал — запустил сбор результатов с Unix утилит «top» и «ps axl» в Wolfram Language, а затем приступил к их анализу. И одна вещь была совершенно очевидна: очень много системного времени было постоянно задействовано, ядро Linux постоянно было чем-то занято. И, на самом деле, казалось, что замедления могут поступать вовсе не от пользовательского кода; они могут исходить от чего-то, что происходит в ядре операционной системы.

Собственно, это сподвигло меня заняться трассировкой системных вызовов. Я не делал ничего подобного в течение последних почти 25 лет, однако мой прошлый опыт подсказывал, что у меня есть возможность получить большое количество данных, но трудных для интерпретации. Однако теперь в моем распоряжении имеется Wolfram Language.

Запущенная утилита “strace” на Linux, несколько секунд совершая вызовы API, на своем выходе содержала 28,221,878 строк. Однако потребовалось всего лишь несколько строчек кода Wolfram Language для того, чтобы собрать воедино время начала и окончания определённых системных вызовов для построения гистограммы длительности системных вызовов. Проделав это всего для нескольких системных вызовов, я получил это:



Интересно, что мы получили ярко выраженные дискретные пики. И, когда я посмотрел на системные вызовы, соответствующие этим пикам, то казалось, что они все исходят от futex (часть Linux, отвечающая за синхронизацию потоков). Затем я выбрал только вызовы от futex и увидел резкие пики на 250 мс, 500 мс и 1000 мс:



Но были-ли они проблемой в действительности? Вызовы futex, по сути, не активны; они не занимают процессорное время. И, на самом деле, это весьма типичная ситуация — когда некоторые вызовы находятся в состоянии ожидания ввода-вывода для их завершения. Таким образом, для меня наиболее интересный момент состоял в том, что не было никаких других системных вызовов, которые бы занимали сотни миллисекунд.

Значит, тормозит сама операционная система!

Так что же получается? Я начал наблюдать — что же происходит на различных ядрах каждого узла? Теперь Tomcat и другие части нашей инфраструктуры прекрасно справляются с многопоточностью. Тем не менее, оказалось, что то, что вызывает замедления, заставляет тормозить все ядра, даже несмотря на то, что они работают с различными потоками. И единственное, что может это сделать — это ядро операционной системы.

Но что бы заставило ядро Linux вызывать подобные замедления? Я подумал о планировщике. Я не мог понять, почему наша ситуация приводит к неадекватному поведению в планировщике. Но мы всё рассмотрели планировщик и попытались изменить различные настройки. Никакого эффекта.
Затем у меня появилась ещё более странная мысль. Экземпляры Wolfram Cloud, которые я использовал, работали через виртуальные машины. А что если замедление пришло “извне Матрицы”? Я запросил версию Wolfram Cloud, работающую на голом железе — без виртуальной машины. Но до того, как мне её предоставили, я нашёл утилиту, которая измеряет время, уходящее на потери на виртуальную машину, и оно оказалось ничтожно малым.

К этому моменту я занимался этим вопросом по часу-два каждый день. В это время у меня как раз была насыщенная поездка на фестиваль SXSW (см. статью на Хабрахабре "Стивен Вольфрам: Рубежи вычислительного мышления (отчёт с фестиваля SXSW)"). До сих пор профессионалы в нашей команде проектирования облачного ПО активно занимались данным вопросом, и я оставил эту задачу их умелым рукам.

Когда я прилетел обратно, я столкнулся с другими интересными моментами. Мы разделили каждый вызов API на 15 промежуточных действий. Тогда один наш инженер с PhD в области физики сравнил вероятность замедления на каждом шаге (слева) со средним временем, которое тратится на этот шаг (справа):



За одним исключением (которое было вызвано известной причиной) мы получили чёткую корреляцию. Всё выглядело так, как будто ядро Linux (и всё, что работает под его управлением) подпадало под воздействие чего-то непонятного и в совершенно случайное время, вызывая те самые замедления, которые случались в момент вызова какой-то части API.

И мы начали поиск того, что вызывало эти замедления. Следующая подозрительная вещь, которую мы заметили — большое количество операций ввода/вывода. В конфигурации, которую мы проверяли, Wolfram Cloud использовал систему NFS для доступа к файлам. Мы попытались настаивать NFS, менять различные параметры, использовать асинхронный режим, использовать UDP вместо TCP, сменить планировщик ввода/вывода NFS сервера и т. д. Никаких изменений. Мы попытались использовать совершенно другую файловую систему, называемую — Ceph. Такая же проблема. Затем мы попытались использовать в качестве памяти локальный диск. В конце концов, похоже, что это подействовало — большинство замедлений исчезло, но некоторые остались.

Мы приняли это как знак и начали дальше копать в области операций ввода/вывода. Мы провели эксперимент, который включал редактирование огромного блокнота на узле при запуске большого количества вызовов API на тот же узел:



Результат оказался интересным. В течение периода, когда блокнот редактировался (и постоянно сохранялся) вызовы API длились 500 мс вместо 100 мс. Но почему простые файловые операции оказывали такое сильное влияние на все 8 ядер узла?

Виновник найден

Мы начали копать дальше, и вскоре поняли, что простые файловые операции в действительности не являются таковыми, и мы быстро поняли почему. Знаете, где-то пять лет назад, в начале развития Wolfram Cloud, мы хотели поэкспериментировать с отслеживанием версий файлов. И, как опытный образец, кто-то ввёл простую систему управления версий, называемую RCS.

Множество систем программного обеспечения в мире всё еще используют RCS, даже несмотря на то, что он не имел существенных обновений в течение практически 30 лет, и к настоящему времени появились гораздо лучшие решения (как те, что мы используем для бесконечной возможности отмены в блокнотах). Но почему-то тот самый опытный образец RCS никогда не заменялся в нашем Wolfram Cloud codebase — и он всё еще запускался в каждом файле!

Одна особенность RCS состоит в том, что, когда файл изменяется, даже на всего один бит, большое количество данных (размером, иногда, в несколько раз превышающее сам файл) записывается на диск. Мы не были уверены, сколько операций ввода-вывода в целом можно ожидать. Но было ясно, что RCS делает этот процесс неоправданно более интенсивным.

Могут-ли операций ввода/вывода на самом деле повесить всё ядро Linux? Возможно, есть какой-то неизвестный глобальный шлюз. Возможно, дисковая подсистема виснет, потому что она недостаточно быстро сбрасывает заполненные буферы. Возможно, ядро занято повторным отображением веб-страниц для того, чтобы сделать доступными большие части памяти. Могло происходить вообще всё, что угодно, однако было очевидно, что нужно просто заменить RCS и посмотреть, к каким изменениям это приведёт.

Мы сделали это, и, о чудо, эти ужасные замедления сразу исчезли!

Итак, после недели интенсивной отладки мы получили решение нашей проблемы. И, при проведении повторного эксперимента, теперь всё работало как надо — время вызова API полностью превалировало над временем передачи к тестовому кластеру:

Wolfram Language и облако

Чему меня это научило? Во-первых, усилилось моё впечатление, что облачный софт — наиболее трудная (даже враждебная) — среда разработки и отладки, с которой мне приходилось когда-либо сталкиваться. Во-вторых, это заставило меня осознать, насколько ценным является Wolfram Language как своего рода метасистема для анализа, визуализации и организации всего того, что происходит внутри такой сложной системы, как облако.

Что касается отладки, то в этом вопросе я несколько избалован — так как я в подавляющей части пишу на Wolfram Language, где отладка весьма легка, и где мне крайне редко приходилось тратить больше нескольких минут, чтобы найти ошибку. Почему с Wolfram Language заниматься отладкой так легко? Прежде всего, думаю, это потому, что код получается, как правило, краткий и удобочитаемый. Так же код обычно пишут в блокнотах, где его можно тестировать, а каждая часть программы документируется, когда её создают. Так же важной деталью является то, что Wolfram Language — язык символьный, поэтому всегда можно взять любую часть программы, и она будет работать самостоятельно.

Отладка ПО на более низких уровнях — совершенно другой процесс. Он гораздо больше похож на процесс выставления медицинского диагноза, где так же имеют дело со сложными многокомпонентными системами и пытаются поставить диагноз по результатам нескольких измерений или экспериментов (если мыслить аналогиями, то наша проблема управления версий могла бы быть похожа на какой-то ужасный дефект в репликации ДНК).

Всё это приключение в облаке так же весьма подчёркивает то значение, которое мы вкладываем в Wolfram Cloud. Потому что весомая часть того, чем является Wolfram Cloud — ограждение пользователей от всех проблем со сложностями ПО облачной инфраструктуры, дающее им возможность разрабатывать и развертывать что-бы то ни было непосредственно в Wolfram Language.

Конечно, чтобы сделать это возможным, нам самим нужно было построить всю автоматизированную инфраструктуру. И сейчас благодаря этому маленькому приключению в “отладке с научным подходом” мы на один шаг ближе к этому. И действительно, на сегодняшний день, Wolfram Cloud имеет свой API, который работает без каких-либо таинственных квантованных замедлений и быстро приближается к состоянию, когда он полностью сможет выйти из бета-версии.