Простое профилирование Node.js приложений
Для профилирования приложений Node.js доступно множество сторонних инструментов, но во многих случаях проще всего использовать встроенный профайлер Node.js. Встроенный профайлер использует профайлер V8, который делит стек выполняющейся программы на фрагменты через равные промежутки времени. Профайлер представляет результаты этих фрагментов с учетом оптимизаций, таких как Jit-компиляция, в виде ряда тиков:
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(/[!@#$%^&*]/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(/[!@#$%^&*]/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"
и получить на выходе:
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
Открыв обработанный текст в вашем любимом текстовом редакторе, вы увидите различного вида информацию. Файл разбит на секции, которые разбиты по языкам. Взглянем сначала на итоговый раздел:
[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
Мы видим, что на первые три записи приходится 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
Анализ этого раздела требует немного больше работы, чем простой подсчет тиков как выше.
В каждом из вышеприведенных стеков вызовов процент в родительском столбце показывает
процент выборок, для которых функция в строке выше была вызвана функцией в текущей строке.
Например, в среднем стеке для _sha1_block_data_order мы видим,
что вызов _sha1_block_data_order встречался в 11,9% выборок, что мы и так знали
исходя из подсчетов выше. Однако теперь мы также можем сказать,
что он всегда вызывался функцией pbkdf2 внутри модуля crypto Node.js. Мы видим,
что аналогичным образом _malloc_zone_malloc вызывалась практически всегда
той же функцией pbkdf2. Таким образом, используя информацию в этом представлении,
мы можем сказать, что наше вычисление хеша из пароля пользователя составляет
не только указанные 51,8%, а все процессорное время в 3 самых часто вызываемых функциях,
так как вызовы _sha1_block_data_order и _malloc_zone_malloc были сделаны
от имени функции pbkdf2.
Теперь становится ясно, что целью нашей оптимизации должна быть генерация хеша на основе пароля. К счастью, вы полностью усвоили преимущества асинхронного программирования и понимаете, что работа по генерации хеша выполняется синхронно и, таким образом, связывает цикл обработки событий. Это лишает нас возможности работать с другими входящими запросами во время вычисления хеша.
Чтобы устранить эту проблему, внесем небольшую модификацию в наши обработчики, используя асинхронную версию функции pbkdf2:
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 для асинхронной версии приложения получаем результат:
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.