「俺の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エンジン のことであり、決して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オプションはこの「いっぺん戻す」作業をログに出します。

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

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

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

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

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

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

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

スクリーンショット 2017-12-02 18.19.18.png

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

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

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

ウワアあぁぁぁああぁああぁ!

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

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

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

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

詳しくはここに記載されていますが、私がまだ読めてません…

--prof

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

node --prof test1.js
スクリーンショット 2017-12-02 18.42.41.png

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

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

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

スクリーンショット 2017-12-02 18.50.56.png

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

--trace-events-enabled

本命

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

スクリーンショット 2017-12-02 18.55.48.png

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

そしたらGoogle Chromeを開いてchrome://tracingとURLを打ち込んでアクセスします1
スクリーンショット 2017-12-02 19.06.10.png

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

スクリーンショット 2017-12-02 19.08.32.png

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

本当に万策尽きたら

V8を讃え、

7189200d3ef6f6f6072642358634d77e5fcfd4ca.jpg

祈りを捧げましょう3

20150731010945306.jpg

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

参考


  1. chromium系のブラウザならGoogle Chrome以外でも対応してそうです。Vivaldiならvivaldi://tracingで使えます。 

  2. なぜか12/3を月曜日と勘違いして「あと1日あるしwww」と余裕ぶっこいてたら時間切れになってしまいました。 

  3. マッドマックスのこのポーズは監督曰く「V8エンジンを表している」。当然ここでのV8エンジンはV型8気筒エンジンです。 

1476496659
テックポエマーと呼ばれてます。