Node.jsのプロファイリングを試してみる

PM2のプロファイリング周りの調査結果とNode.jsでプロファイリングを行ってみた結果です。（[PM2のinstancesの値の変更時の確認方法 - Qiita](https://qiita.com/kitanote/items/68087766e60dc1072b3b)の続き）

## PM2 Pricingについて

|PM2  |PM2  |PM2 Plus  |PM2 Enteprise  |
|---|---|---|---|
|ゼロダウンタイムリロード  |✅  |✅  |✅  |
|ターミナルベースのモニタリング(pm2 monit)  |✅  |✅  |✅  |
|... |...  |... |... |
|CPUプロファイリング  |  | |✅  |

[PM2 - Pricing](https://pm2.io/pricing)

## PM2 PlusでもCPUプロファイリング可能？

PM2 PlusでもCPUプロファイリングができるみたいなドキュメントが存在しますが、Enterprise限定のようです。

[Memory & CPU Profiling \| Guide | PM2 Plus Documentation · Issue #212 · keymetrics/doc-pm2 · GitHub](https://github.com/keymetrics/doc-pm2/issues/212)

## Node.jsでプロファイリングを行う

PlusでCPUプロファイリングできるなら課金しようと思いましたが、Enterpriseの契約はめんどくさそうなので今回はPM2を使わずにプロファイリングを行います。


<details><summary>今回使用したコードはこちら</summary><div>

``` app.js
const express = require("express");
const crypto = require("crypto");
const app = express();

server = app.listen(3000, function(){
    console.log("Node.js is listening to PORT:" + server.address().port);
});

let users = [];

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);
    }
});

app.get('/auth2', (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);
        }
    });
});
```
</div></details>

参考：[Node.js アプリケーションの簡単なプロファイリング \| Node.js](https://nodejs.org/ja/docs/guides/simple-profiling/)

```
# ApacheBenchを利用するためhttpdをインストール
yum install httpd -y
# 今回PM2は使わないことにしたのでstopしておく
pm2 stop test-app
node --prof app.js
# ユーザー作成
curl -X GET "http://localhost:3000/newUser?username=matt&password=password"
# ベンチマークテスト
ab -k -c 20 -n 250 "http://localhost:3000/auth?username=matt&password=password"
```

<details><summary>ベンチマーク結果</summary><div>

```
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Finished 250 requests


Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /auth?username=matt&password=password
Document Length:        2 bytes

Concurrency Level:      20
Time taken for tests:   20.130 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      57250 bytes
HTML transferred:       500 bytes
Requests per second:    12.42 [#/sec] (mean)
Time per request:       1610.378 [ms] (mean)
Time per request:       80.519 [ms] (mean, across all concurrent requests)
Transfer rate:          2.78 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:    81 1543 263.8   1610    1697
Waiting:       78 1543 263.9   1610    1697
Total:         81 1543 263.7   1610    1697

Percentage of the requests served within a certain time (ms)
  50%   1610
  66%   1612
  75%   1612
  80%   1613
  90%   1614
  95%   1614
  98%   1615
  99%   1615
 100%   1697 (longest request)
```
</div></details>

```
# 人が読みやすいファイルに変換
node --prof-process isolate-0x3d49da0-16098-v8.log > processed.txt
cat processed.txt
```


同期バージョンのpbkdf2関数を使用した後のプロファイリング結果。

``` processed.txt
...

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
  56011   75.3%  __GI_epoll_pwait

  18023   24.2%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  18023  100.0%    v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*)
  18023  100.0%      LazyCompile: ~pbkdf2Sync internal/crypto/pbkdf2.js:45:20
  17951   99.6%        LazyCompile: ~<anonymous> /var/www/test/app.js:29:18
  17951  100.0%          LazyCompile: ~handle /var/www/test/node_modules/express/lib/router/layer.js:86:49
  17951  100.0%            LazyCompile: ~next /var/www/test/node_modules/express/lib/router/route.js:114:16
```

## コード改善後のプロファイリング結果

ベンチマーク結果は差がありませんでした。（Nodeのバージョンが`v12.20.0`）

<details>
<summary>変更後のベンチマーク結果</summary>
<div>

```
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Finished 250 requests


Server Software:        
Server Hostname:        localhost
Server Port:            3000

Document Path:          /auth?username=matt&password=password
Document Length:        2 bytes

Concurrency Level:      20
Time taken for tests:   20.287 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      57250 bytes
HTML transferred:       500 bytes
Requests per second:    12.32 [#/sec] (mean)
Time per request:       1622.975 [ms] (mean)
Time per request:       81.149 [ms] (mean, across all concurrent requests)
Transfer rate:          2.76 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       0
Processing:    86 1564 237.9   1619    1657
Waiting:       82 1564 238.0   1619    1657
Total:         86 1564 237.8   1619    1657

Percentage of the requests served within a certain time (ms)
  50%   1619
  66%   1629
  75%   1634
  80%   1635
  90%   1643
  95%   1647
  98%   1656
  99%   1657
 100%   1657 (longest request)
```

</div>
</details>

``` processed.txt
...
 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
  94151   98.9%  __GI_epoll_pwait
```

## Apache Benchの引数を変更

```
# 改善前のコード、同時接続200、合計250リクエスト
 ab -k -c 200 -n 250 "http://localhost:3000/auth?username=matt&password=password"
> apr_socket_recv: Connection reset by peer (104)
```

```
# 改善後のコード、同時接続200、合計250リクエスト
 ab -k -c 200 -n 250 "http://localhost:3000/auth2?username=matt&password=password"
```

同時接続20であればパフォーマンスに影響はありませんでしたが、200にしたところ改善前のコードでは`apr_socket_recv: Connection reset by peer (104)`が返ってきました。また、同条件でpm2で起動した場合は改善前のコードでも正常に実行されました。（PM2のプロセス数を見直す際にはApache Benchでテストしてみる）

参考：[Apache Benchでサクッと性能テスト - Qiita](https://qiita.com/flexfirm/items/ac5a2f53cfa933a37192)