Предыдущие части: Часть 1
Понимание проблемной области
В кратком руководстве Clinic Doctor говорится что, если задержки Event Loop на уровне, который мы наблюдаем, весьма вероятно, что одна или несколько функций «блокируют» Event Loop.
Работая с Node.js очень важно учитывать основную характеристику JavaScript: асинхронные события не могут произойти, пока в настоящее время не выполнен код.
Вот почему setTimeoutне может быть точным.
Например, попробуйте выполнить следующий код в DevTools браузера или в Node REPL:
Результат измерений никогда не покажет 100мс. Скорее всего, он будет в диапазоне от 150 до 250мс. setTimeoutзапланировал асинхронную операцию (console.timeEnd), но текущий код еще не завершен; есть еще две строки. Исполняющийся код называется текущим «тиком». Для завершения тика, Math.random должен быть вызван десять миллионов раз. Если это занимает 100мс, то общее время до выполнения тайм-аута будет 200мс (плюс, функции setTimeout требуется время чтобы фактически поставить тайм-аут в очередь, обычно пару миллисекунд).
Говоря в контексте бэкенда, если операция в текущем тике занимает длительное время, чтобы завершить запросы, она не может быть обработана, и извлечение данных не может произойти, потому что асинхронный код не будет выполняться до завершения текущего тика. Это означает, что «дорогой» в вычислительном смысле код замедлит все взаимодействия с сервером. Поэтому рекомендуется разделить ресурсоемкую работу на отдельные процессы и вызывать их с основного сервера. Это позволит избежать случаев, когда на редко используемом, но «дорогом» маршруте замедляется производительность других часто используемых, но не дорогих маршрутов.
В нашем сервере есть код, который блокирует Event Loop, поэтому следующим шагом будет поиск этот кода.
Анализируем
Один из способов быстро определить плохо выполняющийся код — создать и проанализировать flame graph. Этот граф представляет вызовы функций в виде блоков, расположенных друг над другом — не во времени, а в совокупности. Flame graph называется так, потому что он использует оранжево-красную цветовую схему: чем краснее блок, тем «горячее» функция. То есть,скорее всего она и блокирует Event Loop. Захват данных для flame graph осуществляется путем семплирования CPU — делается снапшот функции которая выполняется и её стека. Цвет определяется процентом времени, в течение которого данная функция находится в топе стека (например, функция выполняется в данный момент) и так для каждого семпла. Если это не последняя функция, которая когда-либо вызывалась в этом стеке, то, скорее всего, она и блокирует Event Loop.
Давайте запустим clinic flame для создания flame graph’а нашего приложения:
В результате в нашем браузере увидим примерно следующее:
Ширина блока показывает, сколько времени у CPU заняло выполнение в целом. Мы видим три основных стека, которые заняли больше всего времени. Все они показывают что server.on самая «горячая» функция. На самом деле, все три стека это одно и тоже. Они расходятся, поскольку во время профилирования оптимизированные и не оптимизированные функции рассматриваются как отдельные фреймы вызовов. Функции с префиксом *оптимизированы движком JavaScript, а функции с префиксом ~не оптимизированы. Если нас не интересует данный показатель, мы можем упростить график, нажав кнопку Merge. Это должно выглядеть примерно так:
Уже сейчас мы можем сделать вывод, что проблемный код в файле util.js.
Медлительная функция также является обработчиком событий: функции, ведут к функции, которая являются частью ядра модуля eventsи server.on. Это резервное имя анонимной функции, представленной в качестве функции обработки событий. Мы также видим, что этот код не относится к тому же «тику», что и код, который обрабатывает запрос. Если бы это было так, функции из ядра http, net и streamмодулей были бы в стеке.
Чтобы найти основные функции нужно раскрыть более мелкие части flame graph. Например, попробуйте использовать поиск в правом верхнем углу интерфейса чтобы найти send (имя внутренних методов из restifyи http). Он должен находиться справа от графика (функции отсортированы по алфавиту):
Обратите внимание, насколько малы все фактические блоки обработки HTTP.
Мы можем нажать на один из блоков, выделенных бирюзовым, чтобы увидеть такие функции, как writeHeadи writeв файле http_outgoing.JS (часть ядра Node библиотека http):
Чтобы вернуться к главному виду, нужно нажать all stacks
Ключевой момент: функция server.on не находится в том же тике, что и фактический код обработки запросов. Несмотря на это она по-прежнему влияет на общую производительность сервера, задерживая выполнение эффективного кода.
Отладка
Благодаря flame graph мы знаем, что проблемной функцией является обработчик событий, передаваемый server.on в файле util.js.
Давайте посмотрим:
Хорошо известно, что криптография, как правило, является затратной, как и сериализация ( JSON.stringify), но почему они не появляются на flame graph? Эти операции семплированы, но они скрыты cpp фильтром. Если мы нажмем кнопку cpp мы увидим следующее:
Внутренние инструкции V8, относящиеся как к сериализации, так и к криптографии, теперь отображаются как самые горячие стеки и занимают большую часть времени. Метод JSON.stringify напрямую вызывает код C++, поэтому мы не видим функции JavaScript. В случае криптографии такие функции, как createHash и update, находятся в данных, но они либо встроены (что означает, что они исчезают в объединенном представлении), либо слишком малы для визуализации.
Как только мы начнем вникать в код в функции etagger, быстро становится очевидным, что она плохо спроектирована. Почему мы берем инстанс serverиз контекста функции? Происходит много хэширования, так ли это необходимо? В реализации также нет поддержки заголовка If-None-Match, которая уменьшила бы некоторые нагрузки в реальных сценариях. Потому что клиенты будут делать только запрос к head для определения актуальности.
Давайте пока проигнорируем эти нюансы и проверим нашу догадку, что фактическая работа выполняемая в server.on действительно бутылочное горлышко. Этого можно добиться, установив код server.on пустой функции и сгенерировать новый flame graph.
Внесите изменения в функцию etagger:
Функция слушателя событий показывает, что в server.on сейчас нет операций.
Давайте снова запустим clinic flame:
Новый flame graph будет выглядеть так:
Выглядит лучше и мы должны были заметить увеличение количества запросов в секунду. Но почему код, генерирующий события такой «красный»? На данный момент мы ожидаем, что код обработки HTTP займет большую часть времени процессора, в server.on вообще нечего выполнять
Этот тип бутылочного горлышка вызван тем, что функция выполняется больше, чем требуется.
Следующий подозрительный код в начале util.js может быть ключом:
Давайте удалим эту строку и запустим процесс с флагом --trace-warnings:
Если мы направим AutoCannon в другой терминал, вот так:
Наш процесс выдаст что-то подобное:
Node говорит нам, что множество ивентов присоединяется к объекту server. Это странно, потому что есть boolean, который проверяет, было ли событие присоединено, а затем возвращается выше, делая attachAfterEvent no-op после прикрепления первого события.
Давайте взглянем на функцию attachAfterEvent:
Условие проверяется неправильно! Оно проверяет attachAfterEventна истинность вместо afterEventAttached. Это означает, что новое событие присоединяется к инстансу server при каждом запросе, а затем все предыдущие прикрепленные события запускаются после каждого запроса. Упс!
В заключительной части оптимизируем наш код. Несколько советов чтобы достичь максимальной производительности. На что следует обращать внимание разработчику на Node.js
Перевод статьи: David Mark Clements Keeping Node.js Fast: Tools, Techniques, And Tips For Making High-Performance Node.js Servers
