对于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);
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 hash = crypto.pbkdf2Sync(password, users[username].salt, 10000, 512);
if (users[username].hash.toString() === hash.toString()) {
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二进制文件捆绑在一起的tick处理器。要运行处理器,请使用--prof-process
标志:
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt
在你最喜欢的文本编辑器中打开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 ++函数占用CPU时间最多的信息,请参阅:
[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
我们发现前三项占该程序占用CPU时间的72.1%。从这个输出中,我们立即看到至少有51.8%的CPU时间被一个称为PBKDF2的函数占用,这个函数对应于我们从用户密码生成的哈希值。然而,我们的应用程序中可能不会立即显示下面两个条目的影响因素(或者如果我们将以例子的方式假装其他条件)。为了更好地理解这些函数之间的关系,我们接下来将看到[自下而上(重型)概要文件]部分,其中提供了有关每个函数的主要调用者的信息。检查本节,我们发现:
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%的样本中,我们从上面的原始计数中知道样本。但是,在这里,我们也可以知道它始终由Node.js加密模块中的pbkdf2函数调用。我们看到类似地,_malloc_zone_malloc几乎完全由同一个pbkdf2函数调用。因此,使用这个视图中的信息,我们可以看出,我们的用户密码的散列计算不仅仅针对51。
在这一点上,非常清楚的是,基于密码的哈希生成应该成为我们优化的目标。值得庆幸的是,您完全内化了异步编程的 好处,并且您意识到从用户密码生成散列的工作正在以同步方式完成,从而捆绑事件循环。这可以防止我们在计算散列时处理其他传入请求。
为了解决这个问题,你需要对上述处理程序进行小小的修改,以使用异步版本的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, (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 tick处理器如何帮助您更好地理解Node.js应用程序的性能。