Дело о пропавшем RPS

Было около одиннадцати. Тёплый летний вечер за окном уже выцвел до черноты. Комнату резал холодный свет монитора, в IDE молча лежал открытый swm-core. Я в компании двух агентов починял примус и оптимизировал горячий путь HTTP. Всё шло слишком спокойно. Такие вечера обычно заканчиваются плохо.

У uWS данные запроса живут только внутри синхронного колбэка. Нужна асинхронность? Переложи в JavaScript метод, URL, query, заголовки и параметры маршрута. На каждое поле приходится отдельный вызов в C++-биндинг.

Я собрал их в req.snapshot(): один нативный вызов вместо пачки. Должно быть как минимум не медленнее. Меньше переходов, те же данные.

Окей, закодил, CI провалидировал, биндинг собрал. Пора тестировать новый горячий путь. Запустил проверку, сижу жду...

few minutes later

С ноги открывается дверь. «У нас упал CI. Похоже, отрицательный рост. По коням!»

Осмотр места преступления

Лил проливной дождь. Одинокий фонарь тускло освещал обочину. Что-то бесформенное и скомканное лежало в нескольких метрах, на границе света и тьмы. Детектив в длинном чёрном тренче и широкополой шляпе тяжело затянулся сигаретой и тихо спросил в темноту: «Ну и кто это говно накодил?» Бросил окурок в лужу и уже громче произнёс: «Ладно. Работаем».

На месте преступления обнаружили:

  • Node.js 24.17.0;
  • @swarmmachina/swm-core 4.1.1;
  • @swarmmachina/swm-uws 0.5.7;
  • @swarmmachina/benchkit 0.2.0;
  • Linux x86_64, Intel Xeon E5-2680 v4.

Сценарий был обыденным: асинхронный GET /base-async возвращает { ok: true }. Сто соединений, конвейеризация 10, четыре рабочих потока.

Помимо потерпевшего, на месте оказались трое подозреваемых:

  • req.snapshot() одним вызовом собирает метод, URL, query, заголовки и параметры маршрута;
  • res.endBatch() одним вызовом отправляет статус, подготовленные заголовки и тело, а затем завершает ответ без отдельных writeStatus(), writeHeader() и end();
  • res.collectBody() собирает чанки входящего тела внутри биндинга и передаёт в Node.js готовый ArrayBuffer.

Для каждого подозреваемого стенд поднимал три сервера: два контрольных с выключенными нативными быстрыми путями и один кандидат, где включён только проверяемый путь. Каждый процесс прогревался 30 секунд. Затем шли 12 раундов по 15 секунд. Кандидат по очереди занимал каждый из трёх процессных слотов, чтобы порядок запуска ему не подыгрывал.

Первая улика

Контроль обрабатывал примерно 138 тысяч запросов в секунду. С req.snapshot() осталось около 102 тысяч.

Кто-то похитил четверть RPS.

Процессорное время на один запрос выросло с 7,3 до 9,9 мкс. p95 поднялся с 7,42 до 10,08 мс, p99 с 8,20 до 10,49 мс.

Быстрый путьСценарийΔ RPSΔ CPU/запросΔ p99
requestSnapshotасинхронный GET−25,55%+34,30%+29,99%
responseBatchподготовленные заголовки−0,62%+0,62%+1,47%
collectBodyPOST, JSON 45 байт+0,78%−0,85%−3,88%

У requestSnapshot центральные 50% парных наблюдений RPS лежали между −31,06% и −24,92%. У двух других подозреваемых диапазон захватил оба знака. Первая улика указывала на одного, но сначала стоило проверить алиби стенда.

Я повторил серии с выключенными быстрыми путями. Один процесс всё равно назывался кандидатом, хотя отличался только ролью в расписании.

И стенд спокойно нарисовал эффекты из воздуха:

  • асинхронный GET: −4,89% RPS;
  • подготовленные заголовки: +5,07% RPS;
  • POST: −1,56% RPS.

Этого хватило, чтобы отпустить res.collectBody() и res.endBatch(): их небольшие сдвиги не удалось отделить от шума. А вот алиби req.snapshot() развалилось. Даже нарисованные стендом −4,89% в контрольном прогоне далеки от измеренных −25,55%, а весь центральный диапазон парных наблюдений остался ниже нуля.

Двух подозреваемых я отпустил. Остался один.

Расследование

Всё выглядело как надо. req.snapshot() делал ровно то, для чего был предназначен. Вместо нескольких переходов между JavaScript и C++ у меня один. Результат тот же: метаданные запроса лежат в одном объекте Node.js. Никаких «дорогих» переходов туда-сюда.

Что-то не сходилось. Все улики указывали на этого подозреваемого, но как он это сделал? Где четверть RPS?

Значит, пора вскрывать код.

Снимаю смешанный профиль JavaScript/C++ через perf. Контрольная сборка выполняет около 22,7 тысячи инструкций и 16,1 тысячи процессорных циклов на запрос. Сборка с req.snapshot() показывает уже 33,5 тысячи инструкций и 24,5 тысячи циклов.

Инструкций стало больше примерно на 47,5%. Циклов на 52,4%.

Лёд тронулся, господа присяжные заседатели.

Границу я действительно пересекал один раз. Но работы на той стороне оказалось примерно в полтора раза больше, чем я ожидал.

req.snapshot() создаёт новый JavaScript-объект, копирует в него строки метода, URL и query, собирает объект заголовков и массив параметров. Данные читаются из uWS, превращаются в значения V8 и записываются в новые свойства. Вверху профиля оказались создание строк и свойств, хеширование, аллокации, смена карты объекта и CreateDataProperty.

Переходов стало меньше. Работы стало больше. Как закодил, так и получилось.

Главное в ходе расследования не выйти на себя.

В стремлении упростить себе жизнь я усложнил жизнь серверу и нативному биндингу. Один широкий вызов спрятал создание целого графа JavaScript-значений и оказался дороже нескольких узких.

Мотив и метод понятны. Но доказательной базы пока не хватает.

Доказательство

По первому профилю нельзя точно сказать, сколько отдельно стоят строки, заголовки, параметры и сама C++-обёртка. В опубликованном .node не сохранился символ RequestSnapshot, поэтому часть нативных кадров осталась адресами.

Чтобы закончить расследование, я пересобрал swm-uws@0.5.7 с отладочными символами и диагностическим переключателем. Затем поочерёдно включал части snapshot().

Это уже отдельный диагностический прогон на том же Xeon и Node.js 24.17.0, а не продолжение парного RPS-бенчмарка. Каждый режим прогревался 30 секунд, затем шли 30 секунд perf stat и 30 секунд perf record. Сервер был закреплён за CPU 2, генератор нагрузки за CPU 3–6.

РежимИнструкций/запросΔ к предыдущему
Старый путь25 430n/a
Один переход, готовый снимок21 403−4 027
Новые контейнеры и пять свойств26 119+4 716
Новые строки имён свойств30 745+4 626
Значения method и URL31 542+797
Пустой query31 522−20
Копирование заголовков36 413+4 890
Пустые параметры маршрута36 485+72
Production snapshot()36 458−27

Один переход с заранее собранным результатом действительно оказался дешевле старого пути примерно на четыре тысячи инструкций. Проблема появилась при материализации результата.

Новые контейнеры и пять свойств добавили 4 716 инструкций. Создание строк с именами свойств добавило ещё 4 626. Значения метода и URL вместе стоили 797. Копирование двух заголовков, Host и Connection, добавило 4 890.

Полный production-снимок выполнял 36 458 инструкций и 29 832 цикла на запрос. Это на 43,37% и 56,29% больше старого пути в этом диагностическом прогоне. Query был пустым, параметров маршрута не было, поэтому их стоимость этот сценарий не раскрывает.

RequestSnapshot наконец появился в профиле, но его собственный кадр занимал лишь 1,21% семплов. Основная работа распределилась по вызовам V8: созданию строк и свойств, аллокациям и смене карты объекта.

Переходов стало меньше, и это действительно помогло. Но весь выигрыш съела безусловная материализация снимка. На одном переходе я сэкономил 4 027 инструкций, а на сборке результата потратил 15 055. В сухом остатке snapshot() добавил 11 028 инструкций на каждый запрос.

Подозреваемый оказался лишь исполнителем. Настоящая ошибка была в контракте: snapshot() безусловно собирал всё и сразу.

Дело можно закрывать.

Приговор

Детектив провёл рукой по недельной щетине, откинулся в кресле и задумчиво посмотрел в монитор. Свет мягко освещал его усталое лицо. «Штирлиц ещё никогда не был так близок к провалу», тихо произнёс детектив. Безжалостно отключил req.snapshot() по умолчанию на горячем пути и отправил коммит крутиться в CI. Началась очередная проверка очередного билда на регрессию.

Даже «богоподобно быстрый» C++ не спасёт плохой контракт.

Это измерение конкретных версий, железа и сценария. Оно не доказывает, что C++, V8 API или нативные модули медленные сами по себе. Вывод уже и без этого достаточно неприятный: меньше переходов через биндинг ещё не означает меньше работы.

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

А пока кушайте кашу, проверяйте релизы на отрицательный рост и не доверяйте слепо своим предположениям.

Что ещё почитать