Node.js 應用程式分析

有許多第三方工具可用於分析 Node.js 應用程式,但在許多情況下,最簡單的選擇是使用內建的 Node.js 分析器。內建分析器使用 V8 內部的分析器,在程序執行期間定期採樣堆疊。它記錄這些採樣的結果,以及重要的優化事件,如即時編譯,作為一系列 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 的源代碼才能解釋這些 ticks。幸運的是,自 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"

並獲得一個 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]:
   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

我們看到前3個條目佔應用程式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 計數更多的工作。在上述每個「呼叫堆疊」中,父列中的百分比告訴您上一行中的函數被當前行中的函數呼叫的樣本百分比。例如,在上面中間的「呼叫堆疊」中,對於 _sha1_block_data_order,我們看到 _sha1_block_data_order 出現在 11.9% 的樣本中,這是我們從上面的原始計數中知道的。但是,在這裡,我們還可以知道它總是被 Node.js crypto 模組內的 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,
    '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 應用程式的性能。

您可能也會發現如何創建火焰圖有所幫助。連結

閱讀時間
7 分鐘閱讀
貢獻
編輯此頁面