Node.js Performance 改善ガイド

Node.js Performance 改善ガイド

Node.js のパフォーマンスについての話がISUCON含めて徐々に増えてきているので、僕が業務でやってるパフォーマンス改善をやる際の流れとその時の方法について説明します。

まず「なんか遅いなぁ」と思って調べると、だいたい「Memory、CPU、FIle、Network」のいずれかが遅くなっていたり、負荷がかかっていることが多いです。このリソースのいずれに負荷がかかっているのかを調べるには top だったりなんだったりで調べてもらい、その後の状況を整理する所からが勝負です。

それぞれ微妙に改善するポイントが違うのでそれぞれどうやって原因を特定して、対策を講じるかについて書いていきます。

Memory の場合

ちなみに僕が負荷計測していて一番よくあるのがメモリです。 Node.js のメモリへの負荷が高まっており、ガベージコレクションが頻発してCPUにも負荷がかかって結果として遅くなる、ということが多いです。

Node.js でも他の言語と同様、一度使ったオブジェクトの開放漏れ、所謂メモリリークが発生するとメモリへの負荷が高まり、この状況に陥ります。

（もちろんメモリリークが原因じゃなく、正当にメモリを使いすぎている可能性もあります）

メモリリークかどうかを特定する

メモリリークが発生するのはどこかのオブジェクトがルートノードと呼ばれる所からアクセス可能なままの状態で放置されており、 v8 がオブジェクトを開放できない時に発生します。

https://www.dynatrace.com/resources/ebooks/javabook/how-garbage-collection-works/

これを判別するには heapdump と呼ばれる手法で解析する必要があります。これはヒープメモリの領域を全て取得し、dumpするという手法です。

これには node-heapdump を利用します。

github.com

node-heapdump を使うと Node.js のヒープメモリ内の状況がわかります。

基本的には require('heapdump') としておくだけで良いです。UNIX系ならば SIGUSR2 のシグナルを送れば勝手に dump ファイルを取得してくれます。 もしも GC をかけてから取得したい場合など何らかの事前処理を伴ってからプログラマブルに取得したい場合は以下の要領で組み込むことも可能です。

const heapdump = require('heapdump')

process.on('SIGUSR1', () => {
  global.gc(); // gc関数は --expose-gc フラグを付ける必要があります。
  heapdump.writeSnapshot('/var/local/' + Date.now() + '.heapsnapshot');
})

ここで取得したダンプファイルは Chrome の DevTools で解析できます。 DevTools のMemoryタブからアクセスして内容を確認します。

メモリ逼迫前と逼迫後の状態でheapdumpを取っておいてそれを比較します。DevToolsで比較操作をした結果が以下の状況です。

ちなみに最近実際に起きたので言うと、 React v15 の Server Side Rendering をしていた時に、React の createElement した時のHTMLオブジェクトがGCで回収されずにメモリを逼迫していました。 React v16にしたら解消されたのでそこまで深追いはしてませんが、特定には heapdump を使いました。

メモリリークではない場合

これは正当にメモリを多く利用するアプリということなので、メモリの拡張を検討しましょう。

Node.js では default で 1.5 GB までヒープメモリを保持しますがそれ以上になると Out of Memory でプロセスが終了します。これを拡張しましょう。

Frequently Asked Questions · nodejs/node Wiki · GitHub

A: By default, --max_old_space_size (which controls the upper limit of the V8 heap) is ~1.5GB. 

$ node --max_old_space_size=2048 index.js

この他にも --trace_gc や --trace_gc_verbose といったGarbage Collectionが起きたときの詳細なログを取る方法もあります。これらを使って適切なタイミングで GC がかかっているかを調査するというのも手です。

--trace_gc // GCが起きた時にログを出力する

--trace_gc_verbose // GCが起きたときのログを詳細に出力する

これらの他にもGCのタイミングを調整する方法もあります。Node.jsではidleの時にGCを行いますが、それとは別のタイミング(メモリの状況に応じて)で実施することもできます。ただあまり使ったことはないです。

--min_semi_space_size (semispace(CopyGCにおいて、fromからtoへコピーされているがまだ残っているもの)の最小サイズ)

--max_semi_space_size (semispaceの最大サイズ)

--semi_space_growth_factor (semispaceの成長率)

CPU の場合

CPU高負荷で相談される事もメモリの次くらいに多いです。

僕がよく相談されるのは「開発中は気づかなかったけど、最大想定ユーザー数を見越して高負荷計測をした所、CPUに負荷がかかりすぎて想定ユーザー数をさばききれない」という問題です。高負荷測定ではCPUが高負荷になることも多いのですが、負荷がそこまでかかっていないのにCPUが100%になった場合はどこの処理に時間がかかっているのかを確認する必要があります。

どこの処理に時間がかかっているのかを確認する

いくつか紹介します。

• Nodeでv8 simple profilerを使ってprofileする方法でまずは粗く計測する方法
• flame graph を使ってどこにCPU負荷がかかっているのかを画像で確認する方法

これらで粗く問題領域を特定したあとは performance.now() だったり、 console.time だったりで関数の内部でどれだけ時間がかかるのかを計測して犯人探しをします。

v8 simple profiler

v8 が提供してくれているプロファイラをNode.jsから呼び出すという方法です。

Easy profiling for Node.js Applications | Node.js

$ node --prof index.js // これを実行すると isolate-0xNNNNNNNN-v8.log が出力される
$ node --prof-process isolate-0xNNNNNNNNN-v8.log // 注意: Node v9.0.0 - v9.2.0 では isolate-0xNNNNNNNNNN-v8.log のファイルの末尾に不正な行があり何も表示されない。最後の末尾の行を消せば動く。

これを使うとどこでCPUヘビーな処理が行われているかの概略を表示してくれます。

Statistical profiling result from isolate-0x103800000-v8.log,

 [Shared libraries]: 
   ticks  total  nonlib   name
     14    9.4%          /usr/lib/system/libsystem_platform.dylib
      9    6.0%          /usr/lib/system/libsystem_kernel.dylib
      2    1.3%          /usr/lib/system/libsystem_c.dylib
      1    0.7%          /usr/lib/system/libsystem_malloc.dylib

 [JavaScript]:
   ticks  total  nonlib   name
    109    1.2%    2.4%  LazyCompile: *EventEmitter events.js:11:22
     80    0.9%    1.8%  LazyCompile: *ReadableState _stream_readable.js:35:23
     75    0.8%    1.7%  LazyCompile: *IncomingMessage _http_incoming.js:20:25

 [C++]:
   ticks  total  nonlib   name
     24   16.1%   19.5%  t node::(anonymous namespace)::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
     10    6.7%    8.1%  t node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
....

 [Summary]:
   ticks  total  nonlib   name
      2    1.3%    1.6%  JavaScript
     90   60.4%   73.2%  C++
      4    2.7%    3.3%  GC
     26   17.4%          Shared libraries
     31   20.8%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
     40   59.7%   26.8%  T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
     19   28.4%   12.8%  T v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
....

 [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
     20   17.2%  UNKNOWN
      2   10.0%    T v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
      1   50.0%      LazyCompile: ~startup bootstrap_node.js:13:19
      1  100.0%        Script: ~<anonymous> bootstrap_node.js:10:10
      1   50.0%      LazyCompile: ~emitNone events.js:113:18
      1  100.0%        LazyCompile: ~emit events.js:165:44
      1  100.0%          LazyCompile: ~resume_ _stream_readable.js:822:17
      1  100.0%            LazyCompile: ~_combinedTickCallback internal/process/next_tick.js:129:33
      1    5.0%    T v8::internal::Builtin_FunctionPrototypeBind(int, v8::internal::Object**, v8::internal::Isolate*)
      1  100.0%      Script: ~<anonymous> dns.js:1:11
      1  100.0%        LazyCompile: ~NativeModule.compile bootstrap_node.js:589:44
      1  100.0%          LazyCompile: ~NativeModule.require bootstrap_node.js:521:34
      1  100.0%            Script: ~<anonymous> net.js:1:11

....

このファイルの中で僕がまず見るのは [Summary] です。 JavaScript , C++, GC, Shared librariesのいずれで負荷がかかっているのかを見ます。 GCの場合はメモリを解析しますし、JavaScript、C++ の場合はそれぞれ [JavaScript] [C++] のカテゴリに書かれている内容を見てCPUを使ってる処理を特定します。

[JavaScript] のセクションは JavaScript の処理でCPU負荷がかかっているものがリストアップされます。その際に RegExp や LazyCompile といったラベルが出てくることがありますが、これはそれぞれ処理の内容の概略を表しています。

• RegExp: 正規表現が実行されています。正規表現は新しく RegExp オブジェクトを構築するのと、正規表現用のコンパイルが実行されるので、v8エンジンにとってのコストは軽くないです。普通に文字列を含むとかの計算をするだけなら indexOf とか includes とかを使う方がコスト的には安いです。
• LazyCompile: 何らかの理由で遅延コンパイルになっています。v8の実行中に最適化がかかれば高速になりますがそれまでは高速化されません。ちなみに LazyCompile: *EventEmitter events.js:11:22 のように * が関数の先頭についていれば最適化された事を示し、 LazyCompile: ~NativeModule.compile bootstrap_node.js:589:44 のように ~ が関数の先頭についた場合は最適化が実行されなかったという事を示しています。
• Builtin: ビルトインで組み込まれている JavaScript 関数です。Math.abs とか JSON.parse とかが該当します。ここがCPU 100%になってると標準関数の使い方が悪かったり、 JSON に巨大なオブジェクトを渡していたりする場合が多いです。

[C++] のセクションでは、 JavaScriptから C++に処理が遷移したあとのCPU実行状況を示しています。ここで出てくるのは v8 が実際に中で行っている処理の関数が出てくることが多いので、このレイヤで何かしようとしてもNode.jsのアプリケーションレベルでは厳しいときが多いです。

[Bottom up (heavy) profile] のカテゴリには実際にCPU負荷が高かったいくつかのポイントをリストアップし、それのコールスタックを表示しています。コールスタックが見れるのでどこの関数で負荷が高い処理をしているかが分かるようになっています。

flame graph を取得する

v8 simple profiler はどこの処理が負荷が高いのか概要をつかむときには使えますが、実際にどういう事をすると負荷がかかるのかわかっている時は flame graph でみたほうが分かりやすいです。

flame graph そのものが何なのかを分かっていない方はこの記事に詳しく書いてあるのでご一読ください。

www.brendangregg.com

日本語だとこの記事が分かりやすかったです。

http://deeeet.com/writing/2016/05/29/go-flame-graph/

Node.js には 0x と呼ばれる npm module があるのでそれを使うと MacOS や Unix 環境では簡単にグラフを取得することができます。

www.npmjs.com

$ npm i 0x -g
$ 0x index.js
// sudo が必要なので password が求められることが有ります。

何回か処理をした後プログラムを終了すると下記のようなグラフが出力されます。

x軸の長さが登場した回数を表し、y軸がコールスタックの深さを示しています。コールスタックが深ければ深いほど関数呼び出しの回数が多いので負荷がかかります。ループの中で呼ばれていたりして何度も実行されているとx軸が長くなります。CPUが100%だったりして返ってこないという時はこのコールスタックの一番上が何かで特定すると分かりやすいです。

File の場合

File IOがボトルネックになるアプリケーションに遭遇したことはあまり無いです。たまに聞くケースで言うと、「Node.jsで大きなファイルの読み込み・書き込みをした時に遅い」と言われることがあります。例えば「ファイルアップロードするシステムを作っていて大きなサイズのファイルのアップロードが遅くなる」とか、「大きなサイズのファイルをダウンロードするのが遅い」とかそういう話ですね。

ただこういう大きなファイルを扱うアプリケーションはそもそもスケールさせるのが難しいのでバッチか何かで別途ファイルを生成して nginx であったり CDN に載せてアプリケーションサーバでサーブしないようにする方が良いです。アップロードもアプリケーションサーバを経由させず、S3に直接PUTするといった方法を取る事が多いです。

まずはそういう方法で回避できないか検討し、どうしてもアプリケーションサーバで扱う必要が出てきた時のみチューニングを実施します。

Node.js は御存知の通り非同期を基本としているので blocking することは基本的にはないのですが、容量が大きい場合は多少状況が異なります。

大きなサイズのファイルをどうしても扱う時

Node.js は非同期を基本としていますが、大きなファイルを扱う場合は気をつける必要があります。

const http = require('http')
const fs = require('fs')
const { promisify } = require('util')
const readFile = promisify(fs.readFile)

const server = http.createServer(async (req, res) => {
  res.writeHead(200, {
    "Content-Type": "application/octet-stream",
    "Content-Size": 1000000000, // 1GB のファイル
  })
  // fsのreadFileを行ってdata.txtを読み込む
  // ただこのファイルが1GBとかある場合はこうすると、一気にメモリが消費されるとともに
  // File IOも負荷がかかってしまう。
  const data = await readFile(__dirname + '/data.txt')
  res.end(data)
});
server.listen(3000)

このコードを実際に動かし、並列でファイルをダウンロードしてみると、Node.jsのプロセスがメモリをどんどん使ってしまい、結果として File IOとメモリの両方に負荷がかかって遅くなるのを感じると思います。

そこでよく使われるのが少しずつ chunked でファイルをもってくる Stream です。

const http = require('http')
const fs = require('fs')

const server = http.createServer((req, res) => { 
  res.writeHead(200, {
    "Content-Type": "application/octet-stream",
    "Content-Size": 1000000000, // 1GB のファイル
  })
  const stream = fs.createReadStream(__dirname + '/data.txt')
  stream.pipe(res) // pipe を使ってresponseに書き込む
})
server.listen(3000)

これならファイルサイズが多少大きくても少しずつファイルを読み込み、レスポンスに書き込むのでメモリにもFile I/Oにも優しいです。

ただこれもデフォルトでは64KBずつしかファイルを読み込まないので、ファイルサイズによっては遅く感じることもあります。この状況すらも避けたいのであれば、 Stream の highWaterMark パラメータを自分でチューニングし、バッファサイズを調整する必要があります。

https://nodejs.org/api/stream.html#stream_buffering

const http = require('http');
const fs = require('fs');
const bufferSize = 1000000;

const server = http.createServer((req, res) => {
  res.writeHead(200, {
    "Content-Type": "application/octet-stream",
    "Content-Size": 1000000000, // 1GB のファイル
  })

  // highWaterMark を設定する。ここでは 1MB ずつメモリにバッファリングする
  const stream = fs.createReadStream(__dirname + '/data.txt', { highWaterMark: bufferSize })
  stream.pipe(res)
})
server.listen(3000)

ここでのhighWaterMarkのサイズはレスポンス速度とリソース負荷とのトレードオフを取ることになります。

highWaterMark が増えればバッファリングされる量が増えてファイルの内容をメモリに貯めてから書き込むようになり、レスポンス速度の向上が期待できますが、その分メモリも増えますしFileIOも増えます。highWaterMarkを減らせば今度はレスポンス速度は下がりますが、 メモリやFile IOの負荷は軽減が見込めます。

Network の場合

Network がボトルネックになることは割と多いです。しかし Node.js のレイヤで何かチューニングすることはそんなに多くないです。シチュエーションとしては例えばBackendにAPIサーバが居て、そこに対してリクエストを送ってレスポンスが返るまで待つようなアプリケーション(いわゆるBFF)でBackendのAPIサーバがボトルネックになる、といったケースです。

このような状況の場合、まずは API サーバのチューニングから始まるので APIクライアントである Node.js のレイヤで何かすることはまだ無いです。あるとしたらキャッシュを持ってAPIサーバにリクエストを送る回数を減らすと行った措置でしょうか。

ただし、キャッシュは諸刃の剣です。またBackendのAPIサーバのチューニングをしたいと思っても自分達がハンドリングできない時もあります。そういった場合に Node.js のレイヤでもできることはあります。

keepalive を on にする

Node.js の http client はデフォルトでは keepalive を off に設定されています。

https://nodejs.org/api/http.html#http_new_agent_options

この状況下では、 http の接続を毎回実施している状況になります。http の keepalive を有効にすることで接続するまでの時間を短縮することが可能です。

const http = require('http');
const keepAliveAgent = new http.Agent({ keepAlive: true });
options.agent = keepAliveAgent;
http.request(options, onResponseCallback);

弊社ではBFFから API サーバへの接続に axios を使っていますが、それも keepalive はデフォルトでは off になっているので下記の要領で on にする必要があります。

{
  url: '/user',
  baseURL: 'https://some-domain.com/api/',
  httpAgent: new http.Agent({ keepAlive: true }),
}

ちなみに https の場合も同様です。 https でAPIを叩く場合はTLS接続の負荷を減らせるため、 keepalive の効果は特に大きいです。

しかしながら、 keepalive に対応していないAPIサーバもいますし、また1台に負荷が偏ってしまうのを防ぐため(接続するサーバを分散させるため)に keepalive を意図的に使わないようにしているAPIサーバも居たりします。そういったときにはこの施策は使えないので注意。

http.Agent は keepalive 以外にも下記のチューニングをすることが可能です。

new http.Agent({ 
  keepAlive: true,
  keepAliveMsecs: 10000 // keepaliveが有効になる期間 デフォルトは1秒 (1000)
  maxSockets: Infinity // 何個のsocketを最大同時に接続させるか デフォルトは Infinity
  maxFreeSockets: 256 // 接続している socket のうち、free 状態になってるsocketを最大何個まで確保するか デフォルトは 256
})

その他: 全体的にパフォーマンスを改善するためにやること

今挙げたリソースの観点からだけでなく、全体的にパフォーマンスを改善するために下記のことも検討します。

• JITが効いているかを確認する
• clusterが利用できないか
• C++ addons vs JavaScript library

JIT が効いているかを確認する

v8 は内部で Just In Time compiler (通称JIT) を利用していますが実際に JIT が有効に働くかどうかは記述した JavaScript 次第です。

例えば

• arguments を不適切に利用している場合
• 引数に取り得るtypesが number だったり object だったりで一意に定まらない場合
• ES2017+ などの新しいsyntaxを利用している場合

などなど、JITにとって好ましくない色々なケースが考えられます。

これらの JIT に好ましくないケースを回避してコードがうまく実行できるかどうかに関しては、いくつかのオプションを有効にしてログを取りながら確認する必要があります。

$ node --trace-opt --trace-deopt  --trace_ic index.js

それぞれ以下の意味があります。

--trace-opt JITがoptimizeしているかどうかをロギングする。

--trace-deopt JITがoptimizeできずにdeoptimizationが起きているかどうかをロギングする。deoptimizeが発生するとログが表示される

--trace_ic inline cache の状態をロギングする。

この他にも --print-opt-code といったoptimize後のコードを表示するオプションも存在します。

この中でよく見るのは --trace-deopt ですが、これを実行するとかなりの量のログが出力されます。 しかも Node.js の標準ライブラリ内のJavaScriptでも稀に deoptimization が発生しているので自分の関係のあるログだけフィルターして見ることをオススメします。

$ node --trace-deopt index.js | grep mysample

自分のコードであればなるべく deoptimization が発生しないようにコードを修正します。

よく見る deoptimizationの発生事例 で言うと、

• babel が REST/Spread operatorをトランスパイルした結果、 arguments に触るようになってしまい、deoptimization が起きるというケース
• 関数が object の型のものも、 string の型のものも引数で受け付けるように柔軟な関数を定義しているケース

です。

前者の例ではServer Side では deoptimization が起きないように babel の設定を見直したりします。 後者の例は最近は型が付けられるようになってきたので発生しにくくなりましたが、それでもdeoptimizationが発生した場合は関数定義を分けて対応するように修正します。

clusterが使えないか検討する

Node.js はシングルスレッドですが、clusterを使うとマルチプロセスで並列性が上がります。CPUコアが複数利用できるなら検討したほうがパフォーマンスが上がることが多いです。 clusterは普通のNode.jsのchild_processを使ったものでメモリの共有はできませんが、並列で計算させるのには使えます。また、最近では pm2 が cluster に簡単に変換させることもできるようにしているので、 pm2 を使っていれば簡単に cluster 化を行うことが可能です。

pm2.keymetrics.io

cluster も若干チューニングポイントが有ります。clusterは基本的に Round Robin されるように各種Worker プロセスに平等にリクエストを渡す作りになっています。リソース効率を上げるのであればこの方がオススメですが、どのWorkerに渡したかという情報をスケジューリングして上げる必要があるので前処理があります。この前処理すら不要でさっさと Worker に渡して速度を上げて欲しいという場合であれば、 cluster の schedulingPolicy を調整する必要があります。

https://nodejs.org/dist/latest-v9.x/docs/api/cluster.html#cluster_cluster_schedulingpolicy

$ NODE_CLUSTER_SCHED_POLICY=none node cluster.js // こうすると Round Robin をやめてランダムに渡すようになる

ただ経験上、このようなスケジュールポリシーにまで手を入れるような事は無いです。むしろ Round Robin のままのが都合が良い事が多いです。

C++ addons vs JavaScript libraries

これは npm に上がっているライブラリを使う時に検討する事ですが、基本的に JavaScript で書かれたライブラリの方を選択するようにしています。

これは互換性だったり運用性もJavaScriptで書かれた物の方が上なのですが、パフォーマンスについてもよっぽどのことがない限りは Pure JavaScript のライブラリのが十分に高速です。 C++ addons の場合、 JavaScript のレイヤから C++のレイヤを呼び出すときのオーバーヘッドがあるので、そのオーバーヘッドを無視できるくらい C++ で複雑な計算をする場合は利点があります。

しかしそうじゃない場合、特に頻繁にそこの計算処理を呼び出す場合においては普通に JavaScript で実装されている方がJITが効くことによって大体において高速です。

まとめ

• どの計算資源に負荷がかかっているかによって状況の整理方法は異なります。
• Memory だったら heapdumpを取りましょう。
  • その後ヒープの差分を見ながら犯人を探しましょう。
• CPUだったらまずは profile しましょう。
  • その後怪しい処理に目をつけたら Performance API か console.time で犯人を探しましょう。
• File だったらまずは処理をアプリケーションの外に出せないか検討しましょう。
  • もしも外だしできなかったら Stream の利用を検討しましょう。
  • 必要に応じて Stream の highWaterMark でチューニングしましょう。
• Network だったらまずは呼び出し先の状況を整理し、呼び出し先で解決できないか検討しましょう。
• 呼び出し先の情報をキャッシュできないかを検討しましょう。
• 必要に応じてkeepaliveオプションを有効にして接続にかかる負荷を軽減させましょう。
• その他以下のことは余裕がある範囲で検討しましょう。
  • JIT が効いてるかどうか
  • cluster が使えるかどうか(これは設計時に検討したほうが良いです)
  • Pure JavaScript のモジュールを選んでいるかどうか (これも設計時に検討した方が良いです)

参考資料

• https://github.com/bnoordhuis/node-heapdump
• https://github.com/nodejs/node/wiki/Frequently-Asked-Questions
• http://www.brendangregg.com/flamegraphs.html
• https://blog.continuation.io/node-js-profiling-using-the-v8-tick-profiler/
• http://tejom.github.io/general/nodejs/v8/debugging/2017/01/16/nodejs-and-v8.html
• http://deeeet.com/writing/2016/05/29/go-flame-graph/
• https://nodejs.org/en/docs/guides/simple-profiling/
• https://www.npmjs.com/package/0x
• https://nodejs.org/api/stream.html#stream_buffering
• https://nodejs.org/api/http.html#http_new_agent_options
• http://pm2.keymetrics.io/docs/usage/cluster-mode/#cluster-mode
• https://nodejs.org/dist/latest-v9.x/docs/api/cluster.html#cluster_cluster_schedulingpolicy
• https://speakerdeck.com/yosuke_furukawa/turbo-boost-next-node-dot-js