LoginSignup
0
0

More than 3 years have passed since last update.

@kitanote

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

Last updated at Posted at 2021-01-03

PM2のプロファイリング周りの調査結果とNode.jsでプロファイリングを行ってみた結果です。（PM2のinstancesの値の変更時の確認方法 - Qiitaの続き）

PM2 Pricingについて

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

PM2 - Pricing

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

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

Memory & CPU Profiling | Guide | PM2 Plus Documentation · Issue #212 · keymetrics/doc-pm2 · GitHub

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

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

今回使用したコードはこちら
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);
        }
    });
});

参考：Node.js アプリケーションの簡単なプロファイリング | Node.js

# 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"

ベンチマーク結果
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)


# 人が読みやすいファイルに変換
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）


変更後のベンチマーク結果
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)


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

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0