Профилирование приложений Node.js

Существует множество сторонних инструментов для профилирования приложений Node.js, но во многих случаях проще всего использовать встроенный профилировщик Node.js. Встроенный профилировщик использует внутренний профилировщик V8, который с определенной периодичностью во время выполнения программы выборочно анализирует стек. Он записывает результаты этих выборок вместе с важными событиями оптимизации, такими как JIT-компиляции, в виде серии тиков:

bash

code-creation,LazyCompile,0,0x2d5000a337a0,396,"bp native array.js:1153:16",0x289f644df68,~
code-creation,LazyCompile,0,0x2d5000a33940,716,"hasOwnProperty native v8natives.js:198:30",0x289f64438d0,~
code-creation,LazyCompile,0,0x2d5000a33c20,284,"ToName native runtime.js:549:16",0x289f643bb28,~
code-creation,Stub,2,0x2d5000a33d40,182,"DoubleToIStub"
code-creation,Stub,2,0x2d5000a33e00,507,"NumberToStringStub"

Раньше для интерпретации тиков требовался исходный код V8. К счастью, начиная с Node.js 4.4.0 появились инструменты, которые облегчают обработку этой информации без отдельной сборки V8 из исходного кода. Давайте посмотрим, как встроенный профилировщик может помочь получить представление о производительности приложения.

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

javascript

app.get('/newUser', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || users[username]) {
    return res.sendStatus(400)
  }
  const salt = crypto.randomBytes(128).toString('base64')
  const hash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512')
  users[username] = { salt, hash }
  res.sendStatus(200)
})

и другой для проверки попыток аутентификации пользователя:

javascript

app.get('/auth', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || !users[username]) {
    return res.sendStatus(400)
  }
  const { salt, hash } = users[username]
  const encryptHash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512')
  if (crypto.timingSafeEqual(hash, encryptHash)) {
    res.sendStatus(200)
  } else {
    res.sendStatus(401)
  }
})

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

Теперь предположим, что мы развернули наше приложение, и пользователи жалуются на высокую задержку запросов. Мы можем легко запустить приложение со встроенным профилировщиком:

bash

NODE_ENV=production node --prof app.js

и нагрузить сервер с помощью ab (ApacheBench):

bash

curl -X GET "http://localhost:8080/newUser?username=matt&password=password"
ab -k -c 20 -n 250 "http://localhost:8080/auth?username=matt&password=password"

и получить вывод ab:

bash

Concurrency Level:      20
Time taken for tests:   46.932 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    5.33 [#/sec] (mean)
Time per request:       3754.556 [ms] (mean)
Time per request:       187.728 [ms] (mean, across all concurrent requests)
Transfer rate:          1.05 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   3755
  66%   3804
  75%   3818
  80%   3825
  90%   3845
  95%   3858
  98%   3874
  99%   3875
 100%   4225 (longest request)

Из этого вывода мы видим, что мы обрабатываем только около 5 запросов в секунду и что средний запрос занимает чуть менее 4 секунд в обе стороны. В реальном примере мы могли бы выполнять много работы во многих функциях от имени пользовательского запроса, но даже в нашем простом примере время может теряться на компиляцию регулярных выражений, генерацию случайных солей, генерацию уникальных хэшей из паролей пользователей или внутри самой структуры Express.

Поскольку мы запустили наше приложение с помощью опции --prof, файл тиков был сгенерирован в том же каталоге, что и локальный запуск приложения. Он должен иметь формат isolate-0xnnnnnnnnnnnn-v8.log (где n — цифра).

Чтобы понять этот файл, нам нужно использовать процессор тиков, включенный в бинарный файл Node.js. Чтобы запустить процессор, используйте флаг --prof-process:

bash

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

Открытие processed.txt в вашем любимом текстовом редакторе предоставит вам несколько различных типов информации. Файл разделен на секции, которые в свою очередь разделены по языкам. Сначала мы посмотрим на секцию summary и увидим:

bash

[Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
      7    0.0%    0.0%  GC
    767    2.0%          Shared libraries
    215    0.6%          Unaccounted

Это говорит нам о том, что 97% всех собранных выборок произошли в коде C++ и что при просмотре других разделов обработанного вывода мы должны уделять больше внимания работе, выполняемой в C++ (в отличие от JavaScript). Имея это в виду, мы далее находим раздел [C++], который содержит информацию о том, какие функции C++ занимают больше всего времени ЦП, и видим:

bash

 [C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

Мы видим, что три верхние записи составляют 72,1% времени ЦП, затраченного программой. Из этого вывода мы сразу видим, что как минимум 51,8% времени ЦП занимает функция под названием PBKDF2, которая соответствует нашей генерации хэша из пароля пользователя. Однако может быть не сразу очевидно, как два нижних элемента учитываются в нашем приложении (или если это так, мы будем притворяться, что это не так, ради примера). Чтобы лучше понять взаимосвязь между этими функциями, мы далее посмотрим на раздел [Bottom up (heavy) profile], который предоставляет информацию о основных вызывающих объектах каждой функции. Изучив этот раздел, мы обнаруживаем:

bash

  ticks parent  name
  19557   51.8%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  19557  100.0%    v8::internal::Builtins::~Builtins()
  19557  100.0%      LazyCompile: ~pbkdf2 crypto.js:557:16
   4510   11.9%  _sha1_block_data_order
   4510  100.0%    LazyCompile: *pbkdf2 crypto.js:557:16
   4510  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30
   3165    8.4%  _malloc_zone_malloc
   3161   99.9%    LazyCompile: *pbkdf2 crypto.js:557:16
   3161  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30

Разбор этого раздела требует немного больше работы, чем приведенные выше необработанные значения тиков. Внутри каждого из приведенных выше «стеков вызовов» процент в столбце parent указывает процент выборок, для которых функция в строке выше вызывалась функцией в текущей строке. Например, в среднем «стеке вызовов» выше для _sha1_block_data_order мы видим, что _sha1_block_data_order встречалась в 11,9% выборок, что мы знали из необработанных подсчетов выше. Однако здесь мы также можем сказать, что она всегда вызывалась функцией pbkdf2 внутри модуля Node.js crypto. Мы видим, что аналогичным образом _malloc_zone_malloc вызывалась почти исключительно той же функцией pbkdf2. Таким образом, используя информацию в этом представлении, мы можем сказать, что наше вычисление хэша из пароля пользователя учитывает не только 51,8% из приведенных выше данных, но и все время ЦП в трех наиболее часто выбираемых функциях, поскольку вызовы _sha1_block_data_order и _malloc_zone_malloc были сделаны от имени функции pbkdf2.

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

Чтобы исправить эту проблему, вы вносите небольшое изменение в приведенные выше обработчики, чтобы использовать асинхронную версию функции pbkdf2:

javascript

app.get('/auth', (req, res) => {
  let username = req.query.username || ''
  const password = req.query.password || ''
  username = username.replace(/[!@#$%^&*]/g, '')
  if (!username || !password || !users[username]) {
    return res.sendStatus(400)
  }
  crypto.pbkdf2(password, users[username].salt, 10000, 512, 'sha512', (err, hash) => {
    if (users[username].hash.toString() === hash.toString()) {
      res.sendStatus(200)
    } else {
      res.sendStatus(401)
    }
  })
})

Новый запуск эталонного теста ab выше с асинхронной версией вашего приложения дает:

bash

Concurrency Level:      20
Time taken for tests:   12.846 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    19.46 [#/sec] (mean)
Time per request:       1027.689 [ms] (mean)
Time per request:       51.384 [ms] (mean, across all concurrent requests)
Transfer rate:          3.82 [Kbytes/sec] received
...
Percentage of the requests served within a certain time (ms)
  50%   1018
  66%   1035
  75%   1041
  80%   1043
  90%   1049
  95%   1063
  98%   1070
  99%   1071
 100%   1079 (longest request)

Ура! Ваше приложение теперь обрабатывает около 20 запросов в секунду, примерно в 4 раза больше, чем с синхронной генерацией хэша. Кроме того, средняя задержка снизилась с 4 секунд до чуть более 1 секунды.

Надеюсь, благодаря исследованию производительности этого (признано искусственного) примера вы увидели, как процессор тиков V8 может помочь вам лучше понять производительность ваших приложений Node.js.

Вы также можете найти информацию о создании flame graph полезной.

Профилирование приложений Node.js ​

Профилирование приложений Node.js