Node.js 指南（轻松分析Node.js应用程序）

轻松分析Node.js应用程序

有许多第三方工具可用于分析Node.js应用程序，但在许多状况下，最简单的选择是使用Node.js内置的分析器，内置的分析器使用V8内部的分析器，在程序执行期间按期对堆栈进行采样，它将这些样本的结果以及重要的优化事件（如jit编译）记录为一系列tick：

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源代码才能解释tick，幸运的是，最近在Node.js 4.4.0中引入了一些工具，能够方便地使用这些信息而无需从源代码单独构建V8，让咱们看看内置的分析器如何帮助提供对应用程序性能的深刻了解。

为了说明tick分析器的使用，咱们将使用一个简单的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"

并获得一个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秒。在实际示例中，咱们能够表明用户请求在许多函数中执行大量工做，但即便在咱们的简单示例中也是如此，编译正则表达式、生成随机salt、从用户密码生成惟一哈希，或者在Express框架内部，时间可能会损失。

因为咱们使用--prof选项运行咱们的应用程序，所以在与本地应用程序运行相同的目录中生成了一个tick文件，它的格式应为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的函数占用，这个函数对应于咱们从用户密码生成哈希。可是，较低的两个条目如何影响咱们的应用程序可能不会当即显而易见（或者若是咱们为了示例而伪装其余方式），为了更好地理解这些函数之间的关系，接下来咱们将看一下[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

解析此部分须要比上面的原始tick计数更多的工做，在上面的每一个“调用堆栈”中，parent列中的百分比告诉你当前行中的函数调用上面行中的函数的样本百分比。例如，在sha1block_data_order上面的中间“调用堆栈”中，咱们看到_sha1_block_data_order出如今11.9％的样本中，咱们从上面的原始计数中知道了。可是，在这里，咱们还能够告诉它始终由Node.js加密模块中的pbkdf2函数调用，咱们看到相似地，_malloc_zone_malloc几乎彻底由相同的pbkdf2函数调用。所以，使用此视图中的信息，能够告诉咱们，用户密码账户的哈希计算不只仅是上面的51.8％，并且对于前3个最多采样函数中的全部CPU时间，由于对_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, (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应用程序的性能。

---

上一篇：入门指南

下一篇：Docker化Node.js Web应用程序