Profiling adventure

本日の Calendar エントリーはパフォーマンスプロファイリングについてで〜す。（よろしくお願いします）

まずはちょっと裏話について説明さしてください。

> 新しい案件では [PointCloud](https://en.wikipedia.org/wiki/Point_cloud) についてアップリを開発しています。PointCloud のデータは普通結構大きくなっているのでプロセシングのために以外メモリや CPU が必要になっています。
> あるポストプロセッサーは全て C(++) で書いてありますが新しい案件は Browser などでも動かないといけない必要があります。[emscripten](https://github.com/kripken/emscripten) を使えば C++ → JavaScript はコンパイルできますが私は C++ あんまり書きたくないし本当に JavaScript で書けないか知りたいです。そのうえできれば WASM か R言語 の比べもしたいですので、長い間やってない Node.js のパーフォマンステストをやりましょうかと考えるようになりました。

私も長い間 Node.js のパフォーマンス問題がなかったので今日はアドベンチャーに行きましょう。:rocket:

プロセッシングのパーフォマンスを Node.js 側に R などと比べるつもりです。全てが同じようなコードベースで動かすためにテストフレームワークを用意しましょうか。

[_`./test/test.js`_]

```javascript
const path = require('path')
const {spawn} = require('child_process')

/**
 * command ... どのプロセスで PointCloud データを読む
 * outFile ... どこのロケーションに保存する
 */
function processPointCloud (command, args, outFile) {
  const child = spawn(command, args)

  // 途中でエラーが行ったら、そのエラーを隠さないようにする
  child.on('error', (e) => console.error(`-- error --\n${e.stack}`))
  child.stdin.on('error', (e) => console.error(`-- error on stdin --\n${e.stack}`))

  // 大きな PointCloud データを読んで...
  fs.createReadStream(path.join(__dirname, 'Serpent Mound Model LAS Data.las'))
　　 // ... プロセッサーに渡す
    .pipe(child.stdin)

  child.stdout.pipe(fs.createWriteStream(outFile))
  // デバッグのために process.stderr コンソールに出力
  child.stderr.pipe(process.stderr, { end: false })
  
  // 終わってからリポートをかきだしましょう
  const report = () => {
    console.log('done')
  }

  child.on('close', report)
}
```

[`'Serpent Mound Model LAS Data.las'`](https://www.liblas.org/samples/Serpent%20Mound%20Model%20LAS%20Data.las) はまあまあ大きな生 PointCloud データサンプルファイル。そのファイルは呼んでプロセスに渡してテストできると思います。

本当のテストを動かすためにあと一つのことがいります：

```javascript
processPointCloud(
  path.join(__dirname, '..', 'pure-js', 'index.js'), // まずは生の JavaScript のテスト
　[], // 今のところはコマンドの変数が使わないですがとりあえずつけましょう。
  path.join(__dirname, 'pure-js.dat') // ← ちゃんとプロセッシングしているかどうかのために出力をファイルに保存しましょう
)
```

なお、`node test/test.js` でこのテストを動かすと何もテストできません。何かを見るために [`hrtime`](https://nodejs.org/dist/latest-v8.x/docs/api/process.html#process_process_hrtime_time) 長昔を使いました。`hrtime` を使って `Date.now()` よりもっと詳しいそのときの時間をもらうことができます。

```javascript
  const start = process.hrtime()
  const report = () => {
    console.log(require('pretty-hrtime')(process.hrtime(start))) 
  }
}
```

そうするとリポートを書き出すには [`pretty-hrtime`](https://www.npmjs.com/package/pretty-hrtime) のおかげで綺麗に時間を表示されてくれます。ただ今日気づきました。[`perf_hooks`](https://nodejs.org/dist/latest-v8.x/docs/api/perf_hooks.html) という新しいコアモジュールが Node 8.5 のリリースが使えるようになりました！`Experimental` だから本当に新しいプロジェクトしか使えないですよ！

```javascript
const {performance} = require('perf_hooks') 
// ...
  performance.mark('start')
  const report = () => {
    performance.mark('stop')
    performance.measure('duration', 'start', 'stop')
    const {duration} = performance.getEntriesByName('duration')[0]
    console.log(`${duration}ms`)
  }
```

書き方は不便かもしれませんがこの API は測定値の不正確が小さくなっています。情報を増やすために[以前に書いたスクリプト](https://gist.github.com/martinheidegger/8180022bd69a254f273bab76856dbb33)を使います。

```javascript
const stats = require('./utils/stats')
// ...
  const report = () => {
    performance.mark('stop')
    stats.finish()
    fs.writeFileSync(`${outFile}.stats.csv`, stats.toCSV())
```

このコードは [`process.cpuUsage`](https://nodejs.org/api/process.html#process_process_cpuusage_previousvalue) と [`process.memoryUsage`](https://nodejs.org/api/process.html#process_process_memoryusage) を使って `.stats.csv` ファイルに 20 データーポイントを CSV で書き出しています［[例](https://gist.githubusercontent.com/martinheidegger/8180022bd69a254f273bab76856dbb33/raw/dfa177fa4fb61cf1313b70094f92c3d2660cf2f2/example_output.csv)］。 Gist に置いてある `visualizer.html` を使うと以下のスクリーショット見たいなグラフが出ています。

![Screenshot](https://gyazo.com/1ad3933ad3dec0b614488202e43073c0.png)

このやり方でとりあえず少しでもプロファイルデバッグできるようになりましたがさらに一つのレベルがあります。Node.js は長い間詳しいプロファイルを書き出せます。

[`--prof`](https://nodejs.org/en/docs/guides/simple-profiling/) フラグで `node` を呼ぶと `node` は v8 のパフォーマンスデーターを保存してくれます。試したいためには `profilePointCloud` の呼び方書き換えないといけません。

```javascript
processPointCloud(
  '/usr/bin/env', // プラットフォームによって `node` のバイナリーが問題になります
  ['node', '--prof', path.join(__dirname, '..', 'pure-js', 'index.js')], // 変数になりました。
  path.join(__dirname, 'pure-js.dat') // ← ちゃんとプロセッシングしているかどうかのために出力をファイルに保存しましょう
)
```

このように呼ぶと [`isolate-0x102801e00-v8.log`](https://gist.githubusercontent.com/martinheidegger/b9c306827d91e42f131551f4fced7147/raw/b00b742eb737a80d501b41dc516d4e2e184004c2/isolate-0x102801e00-v8.log) のようなメモリーログが出てきます。

`node --prof-process isolate-0x102801e00-v8.log` を呼ぶと以下のようなデータが出てきます。

```
Statistical profiling result from isolate-0x102801e00-v8.log, (35137 ticks, 3026 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     23    0.1%          /usr/lib/system/libsystem_pthread.dylib
     17    0.0%          /usr/lib/system/libsystem_malloc.dylib
      2    0.0%          /usr/lib/system/libsystem_platform.dylib

 [JavaScript]:
   ticks  total  nonlib   name
   1885    5.4%    5.4%  Builtin: KeyedStoreIC_Megamorphic
   1591    4.5%    4.5%  Builtin: FastNewClosure
    760    2.2%    2.2%  LazyCompile: *postProcess /Users/m/Documents/node-perf/pure-js/las/pd/pdRecord1.js:23:7
    541    1.5%    1.5%  LazyCompile: *fields.forEach /Users/m/Documents/node-perf/pure-js/util/parser.js:115:20
    515    1.5%    1.5%  Builtin: CompileLazy
    509    1.4%    1.5%  LazyCompile: *_tickCallback internal/process/next_tick.js:151:25
    445    1.3%    1.3%  Builtin: CallFunction_ReceiverIsAny
    437    1.2%    1.2%  LazyCompile: *parse /Users/m/Documents/node-perf/pure-js/util/parser.js:98:14
    422    1.2%    1.2%  LazyCompile: *module.exports /Users/m/Documents/node-perf/pure-js/las/pd/pdRecord1.js:3:18
    415    1.2%    1.2%  LoadIC: A load IC from the snapshot
    378    1.1%    1.1%  LazyCompile: *onwrite _stream_writable.js:422:17
    370    1.1%    1.1%  Builtin: ArgumentsAdaptorTrampoline
    368    1.0%    1.0%  LazyCompile: *Socket._writeGeneric net.js:708:42
    305    0.9%    0.9%  Builtin: Call_ReceiverIsNullOrUndefined
    305    0.9%    0.9%  Builtin: CallFunction_ReceiverIsNotNullOrUndefined
    301    0.9%    0.9%  LazyCompile: *<anonymous> /Users/m/Documents/node-perf/pure-js/util/parser.js:190:12
    299    0.9%    0.9%  KeyedStoreIC: A keyed store IC from the snapshot {1}
...
..
.
```
(全てのファイルなら[こちら](https://gist.githubusercontent.com/martinheidegger/b9c306827d91e42f131551f4fced7147/raw/ece30b9b76f6e9fa232a7e48cce39c7ddc6e6f6d/node--prof-process-isolate-result.txt))

このデーターを使って私はこれからちゃんとデバッグできますがやはりテキストを見るのがちょっとだけ辛いですね。もう一つのやり方があります！

`--inspect-brk` を使うと Node.js はデバッガーと繋がることができます。もう一回書き換える ...

```javascript
processPointCloud(
  '/usr/bin/env', // プラットフォームによって `node` のバイナリーが問題になります
  ['node', '--inspect-brk', path.join(__dirname, '..', 'pure-js', 'index.js')], // 変数になりました。
  path.join(__dirname, 'pure-js.dat') // ← ちゃんとプロセッシングしているかどうかのために出力をファイルに保存しましょう
)
```

...と `node test/test.js`をスタートした後のこのようなメッセージが出てきます。

```
Debugger listening on ws://127.0.0.1:9229/84409de7-d252-45a8-aeaa-d957b90c13b7
For help see https://nodejs.org/en/docs/inspector
```

Chrome のデベロッパーツールバーに新しいアイコンがありますよ！
![テストをスタート前](https://gyazo.com/2df946f8b116550c29c8837567cadec7.png)
&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;↓↓↓↓
![テストをスタート後](https://gyazo.com/ee64644acbed815ce536d9964d78945e.png)

<br/>

いいですね！クリックするとデバッガーがでってきます! :tada:

![デベロッパー画面](https://gyazo.com/f533b419f44eb06c2dd71564cbf84370.png)

<br/>

メモリや Profiler の画面にちゃんとデーターをレコードできます！残念ながらそれはただ `Node.js` のコードのためですので `R` の Implementation とかと比べたいならこのやり方は助かりません。上の visualizer.html または [dtrace](https://nodejs.org/en/blog/uncategorized/profiling-node-js/) を使わないといけませんが一応それでパフォーマンス解決についてもう満足しています。:relieved:

これからは Implementation のパフォマンスをアップするつもりですし、R や emscripten を使って別の Implementation を書くつもりです。進捗について興味があれば [`martinheidegger/las-2`](https://github.com/martinheidegger/las-2) を Watch してください。質問であればぜひ [New Issue](https://github.com/martinheidegger/las-2/issues/new) を使って聞いてください。

ここまで読んでくれてありがとうございました。

良いお年を！ & Merry Christmas!
Martin Heidegger