「俺のNode.jsがこんなに遅いわけがない!」って時に試したいこと


# プロローグ

`node --help`でnodeの起動オプションを見てみると、実はひっそりと`--v8-options`という初心者お断りオーラを醸し出しまくってるオプションがあります。

Node.jsの公式ドキュメントによると

> Print v8 command line options.
> Note: V8 options allow words to be separated by both dashes (-) or underscores (_).
> For example, --stack-trace-limit is equivalent to --stack_trace_limit.

どうやらV8エンジンの起動オプションをnodeコマンドでも与えられるようです。
ついでに、「-」と「_」はどっちでもいいようです。

で、この`--v8-options`を駆使すればNode.jsのパフォーマンスチューニングに役立ちそうって話です。Node.jsを使った開発から離れちゃったから使う機会あるかどうか怪しいけど。

ちなみにこの場合のV8エンジンというのは[Google V8 JavaScriptエンジン](https://ja.wikipedia.org/wiki/Google_V8_JavaScript_Engine) のことであり、決して[V型8気筒エンジン](https://ja.wikipedia.org/wiki/V型8気筒)のことではありません。

# 使ってみよう…その前に

まずは前提としてNode.jsのバージョンはLTSであるv8.9.1とします。
そして使ってみるV8オプションですが、ざっと数えて400ぐらいあるオプション全てを触るのはあまりに辛いので今回は

- `--trace-opt`(`--trace-deopt`)
- `--prof`
- `--trace-events-enabled`

あたりに触れます。

# --trace-opt, --trace-deopt

こいつらについて話す前に、まずNode.js(ていうかV8エンジン)の特性として **実行しながらコードを動的に最適化する** というものがあります。
`--trace-opt`は実行中に最適化が行われたらログが出力さるようにするオプションです。

となると「`--trace-deopt`ってなんや?」となりますが、ここで **動的に最適化する** というのがミソになります。

つまり
V8エンジン「おっしゃこのコード最適化したるで!」
V8エンジン「あ、さっきの最適化やとあかんわ。いっぺん戻してからやり直すけど許してや~」
という状況がNode.jsの実行中にしばしば発生します。

`--trace-deopt`オプションはこの「いっぺん戻す」作業をログに出します。

## で、それどんな時に起こるの?

ここに一つの適当な関数を用意します

```js:test1.js
function testFunc(a) {  
    return a + a;
}

```

例えばこの関数の引数がどちらもnumberで呼ばれた場合、V8エンジンは「お、この関数はnumberの足し算なんやな。それに合わせて最適化したろ。」となります。
しかし、その後に突然stringが放り込まれたりすると、「stringも来るんかい!最適化やり直しや!」となるわけです。

試しにまずは引数をnumberだけにして実行してみましょう。

```js:test1.js
function testFunc(a) {  
    return a + a;
}
 
// 環境によってはログを出力する前にコードを実行し終わってしまう場合があります。
// その場合ログが何も出ないので、適宜ループ回数を調節してください。 
for (let i = 0; i < 1000000; i++) {  
    testFunc(i);
}
```


![スクリーンショット 2017-12-02 18.19.18.png](https://qiita-image-store.s3.amazonaws.com/0/116434/e58fe1a7-1d65-a69d-fcdb-7f6fe87a62f8.png "スクリーンショット 2017-12-02 18.19.18.png")

`optimizing` みたいなログが出力されます。

それではこのコードに少し意地悪をしましょう。

```js:test1.js

function testFunc(a) {  
    return a + a;
}
 
for (let i = 0; i < 1000000; i++) {  
    testFunc(i);
}
 
for (let i = 0; i < 1000000; ++i) {  
    testFunc(i + "");
}

```
![スクリーンショット 2017-12-02 18.25.14.png](https://qiita-image-store.s3.amazonaws.com/0/116434/6019d24a-dec6-be23-ebd4-d26e820c02bd.png "スクリーンショット 2017-12-02 18.25.14.png")

**ウワアあぁぁぁああぁああぁ！**

画面に収まってませんが、`deoptimizing`みたいな文言が出力されてます。
ていうかコードの変更量に対してログ出力の変化が大きすぎる。明らかにただ事ではない。

この「最適化して、やっぱり戻して」みたいなのが何度も繰り返されると、最終的にV8エンジンは「これは最適化できへんわ」と匙を投げますが、ログを見た上で推測するなら結構なリソースが空費されそうです。


## そもそも最適化できないケース

try-catchが使われてるなど、特定のケースではV8エンジンは最初から最適化を諦めます(あるいは単純すぎるから不要と判断します)。

詳しくは[ここ](https://github.com/vhf/v8-bailout-reasons)に記載されていますが、私がまだ読めてません…

# --prof

`--prof`オプションはCPU使用に関するログを残します。
先ほどのコードで試してみましょう。

`node --prof test1.js`
![スクリーンショット 2017-12-02 18.42.41.png](https://qiita-image-store.s3.amazonaws.com/0/116434/6cb3579a-5492-b8a2-9be2-dfdff3b81bcd.png "スクリーンショット 2017-12-02 18.42.41.png")

実行するとisolateうんたらかんたらv8.logというファイルができてますが、中身には人間やめないと読めないような地獄のログが待ってます(君の目で確かみてみろ!)。

人間が読めるように加工する機能はNode.jsに標準で備わってるので安心してください。
~~最初からそうしろよ~~

`node --pref-process [さっき作ったv8.logのファイル名]` で整形してくれますが、それだと標準出力に出力されちゃうので、ちゃんと見たいなら適当なファイルに書き込むようにしましょう。

![スクリーンショット 2017-12-02 18.50.56.png](https://qiita-image-store.s3.amazonaws.com/0/116434/e7847b83-7d93-1630-553b-f80a730a3438.png "スクリーンショット 2017-12-02 18.50.56.png")

まあこれはこれで割と地獄のログなんですが、「あれれ〜、CPU使用率がおかしいぞ~?」って時に使ってみると助けになるかもしれません。

# --trace-events-enabled

**本命**

まずは先ほどのファイルに`--trace-events-enabled` オプションをつけて実行します。

![スクリーンショット 2017-12-02 18.55.48.png](https://qiita-image-store.s3.amazonaws.com/0/116434/a9532fc0-7dfc-0c0f-8621-be9c310a912f.png "スクリーンショット 2017-12-02 18.55.48.png")

node_trace.1.logとかいう怪しいファイルができてますね。

そしたらGoogle Chromeを開いて`chrome://tracing`とURLを打ち込んでアクセスします[^1]。
![スクリーンショット 2017-12-02 19.06.10.png](https://qiita-image-store.s3.amazonaws.com/0/116434/c15d14a9-e4c7-d56a-2614-1d90b7bb4eac.png "スクリーンショット 2017-12-02 19.06.10.png")

こんな画面になるのでLoadボタンから先ほどの怪しげなファイルを読み込みます。
すると何と…!

![スクリーンショット 2017-12-02 19.08.32.png](https://qiita-image-store.s3.amazonaws.com/0/116434/1cf1391b-0cb4-4f0e-f4a2-f5b2d3747f14.png "スクリーンショット 2017-12-02 19.08.32.png")

なんかクライアントサイドでよく使う開発ツールのパフォーマンスタブ的なサムシングが…!!
ちょっとサンプルが短すぎるせいかよくわからないが、何かに使えそうではある。[^2]

# 本当に万策尽きたら
 
**V8を讃え、**

  
![7189200d3ef6f6f6072642358634d77e5fcfd4ca.jpg](https://qiita-image-store.s3.amazonaws.com/0/116434/b0dd8b69-c69a-0bad-5269-885316243d04.jpeg "7189200d3ef6f6f6072642358634d77e5fcfd4ca.jpg")

**祈りを捧げましょう[^3]**

![20150731010945306.jpg](https://qiita-image-store.s3.amazonaws.com/0/116434/a2b39104-88ab-5021-d548-d7458b725f84.jpeg "20150731010945306.jpg")

※ ただの気休めなので、良いエンジニアは真似しないように

# 参考

- [Node.jsのパフォーマンスチューニングのtips](http://abouthiroppy.hatenablog.jp/entry/2017/11/06/095943)
- [Node.jsのパフォーマンス最適化を阻むものの見つけ方](http://postd.cc/how-to-find-node-js-performance-optimization-killers/)

[^1]: chromium系のブラウザならGoogle Chrome以外でも対応してそうです。Vivaldiなら`vivaldi://tracing`で使えます。
[^2]: なぜか12/3を月曜日と勘違いして「あと1日あるしwww」と余裕ぶっこいてたら時間切れになってしまいました。
[^3]: マッドマックスのこのポーズは監督曰く「V8エンジンを表している」。当然ここでのV8エンジンはV型8気筒エンジンです。