Профилирование приложения на Node.js — это измерение его производительности через анализ CPU, памяти и других runtime-метрик во время работы приложения. Это помогает выявлять узкие места, высокое потребление CPU, утечки памяти и медленные вызовы функций, которые могут влиять на эффективность, отзывчивость и масштабируемость приложения.
Существует множество сторонних инструментов для профилирования приложений на Node.js, но во многих случаях проще всего воспользоваться встроенным профилировщиком Node.js. Встроенный профилировщик использует профилировщик внутри V8, который семплирует стек через регулярные интервалы во время выполнения программы. Он записывает результаты этих семплов вместе с важными событиями оптимизации, такими как JIT-компиляции, в виде серии тиков (ticks):
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-приложение. В нашем приложении будет два обработчика: один — для добавления новых пользователей в систему:
app.get('/newUser', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[^a-zA-Z0-9]/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);
});и другой — для проверки попыток аутентификации пользователей:
app.get('/auth', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[^a-zA-Z0-9]/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 — они приведены исключительно в иллюстративных целях. В целом не стоит пытаться проектировать собственные криптографические механизмы аутентификации. Гораздо лучше использовать существующие проверенные решения для аутентификации.
Теперь предположим, что мы развернули приложение, и пользователи жалуются на высокую задержку запросов. Мы легко можем запустить приложение со встроенным профилировщиком:
NODE_ENV=production node --prof app.js
и дать нагрузку на сервер с помощью ab (ApacheBench):
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:
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:
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt
Открыв processed.txt в любимом текстовом редакторе, вы увидите несколько разных типов информации. Файл разбит на секции, которые, в свою очередь, разбиты по языкам. Сначала посмотрим на секцию summary и увидим:
[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++-функции занимают больше всего процессорного времени, и видим:
[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
Мы видим, что на топ-3 записи приходится 72,1% процессорного времени, затраченного программой. Из этого вывода сразу видно, что минимум 51,8% процессорного времени съедает функция PBKDF2, соответствующая генерации хеша из пароля пользователя. Однако не сразу очевидно, как две нижние записи связаны с нашим приложением (а если и очевидно, притворимся, что нет, ради примера). Чтобы лучше понять связь между этими функциями, дальше мы посмотрим на секцию [Bottom up (heavy) profile], которая даёт информацию об основных вызывающих сторонах каждой функции. Изучив эту секцию, находим:
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 внутри
модуля crypto в Node.js. Аналогично видно, что _malloc_zone_malloc вызывался
почти исключительно той же функцией pbkdf2. Таким образом, используя информацию из
этого представления, можно понять, что вычисление хеша из пароля пользователя
отвечает не только за 51,8% сверху, но и за всё процессорное время в трёх самых
семплируемых функциях, поскольку вызовы _sha1_block_data_order и
_malloc_zone_malloc делались в рамках работы функции pbkdf2.
На этом этапе совершенно ясно, что целью нашей оптимизации должна стать генерация хеша на основе пароля. К счастью, вы полностью прониклись преимуществами асинхронного программирования и понимаете, что работа по генерации хеша из пароля пользователя выполняется синхронно и тем самым связывает event loop. Это не даёт нам обрабатывать другие входящие запросы, пока вычисляется хеш.
Чтобы устранить эту проблему, вы вносите небольшое изменение в обработчики выше, чтобы использовать асинхронную версию функции pbkdf2:
app.get('/auth', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[^a-zA-Z0-9]/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 выше с асинхронной версией вашего приложения даёт:
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.