本日の Calendar エントリーはパフォーマンスプロファイリングについてで〜す。（よろしくお願いします）
まずはちょっと裏話について説明さしてください。
新しい案件では PointCloud についてアップリを開発しています。PointCloud のデータは普通結構大きくなっているのでプロセシングのために以外メモリや CPU が必要になっています。
あるポストプロセッサーは全て C(++) で書いてありますが新しい案件は Browser などでも動かないといけない必要があります。emscripten を使えば C++ → JavaScript はコンパイルできますが私は C++ あんまり書きたくないし本当に JavaScript で書けないか知りたいです。そのうえできれば WASM か R言語 の比べもしたいですので、長い間やってない Node.js のパーフォマンステストをやりましょうかと考えるようになりました。
私も長い間 Node.js のパフォーマンス問題がなかったので今日はアドベンチャーに行きましょう。
プロセッシングのパーフォマンスを Node.js 側に R などと比べるつもりです。全てが同じようなコードベースで動かすためにテストフレームワークを用意しましょうか。
[./test/test.js]
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' はまあまあ大きな生 PointCloud データサンプルファイル。そのファイルは呼んでプロセスに渡してテストできると思います。
本当のテストを動かすためにあと一つのことがいります：
processPointCloud(
path.join(__dirname, '..', 'pure-js', 'index.js'), // まずは生の JavaScript のテスト
[], // 今のところはコマンドの変数が使わないですがとりあえずつけましょう。
path.join(__dirname, 'pure-js.dat') // ← ちゃんとプロセッシングしているかどうかのために出力をファイルに保存しましょう
)
なお、node test/test.js でこのテストを動かすと何もテストできません。何かを見るために hrtime 長昔を使いました。hrtime を使って Date.now() よりもっと詳しいそのときの時間をもらうことができます。
const start = process.hrtime()
const report = () => {
console.log(require('pretty-hrtime')(process.hrtime(start)))
}
}
そうするとリポートを書き出すには pretty-hrtime のおかげで綺麗に時間を表示されてくれます。ただ今日気づきました。perf_hooks という新しいコアモジュールが Node 8.5 のリリースが使えるようになりました！Experimental だから本当に新しいプロジェクトしか使えないですよ！
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 は測定値の不正確が小さくなっています。情報を増やすために以前に書いたスクリプトを使います。
const stats = require('./utils/stats')
// ...
const report = () => {
performance.mark('stop')
stats.finish()
fs.writeFileSync(`${outFile}.stats.csv`, stats.toCSV())
このコードは process.cpuUsage と process.memoryUsage を使って .stats.csv ファイルに 20 データーポイントを CSV で書き出しています［例］。 Gist に置いてある visualizer.html を使うと以下のスクリーショット見たいなグラフが出ています。
このやり方でとりあえず少しでもプロファイルデバッグできるようになりましたがさらに一つのレベルがあります。Node.js は長い間詳しいプロファイルを書き出せます。
--prof フラグで node を呼ぶと node は v8 のパフォーマンスデーターを保存してくれます。試したいためには profilePointCloud の呼び方書き換えないといけません。
processPointCloud(
'/usr/bin/env', // プラットフォームによって `node` のバイナリーが問題になります
['node', '--prof', path.join(__dirname, '..', 'pure-js', 'index.js')], // 変数になりました。
path.join(__dirname, 'pure-js.dat') // ← ちゃんとプロセッシングしているかどうかのために出力をファイルに保存しましょう
)
このように呼ぶと 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}
...
..
.
(全てのファイルならこちら)
このデーターを使って私はこれからちゃんとデバッグできますがやはりテキストを見るのがちょっとだけ辛いですね。もう一つのやり方があります！
--inspect-brk を使うと Node.js はデバッガーと繋がることができます。もう一回書き換える ...
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 のデベロッパーツールバーに新しいアイコンがありますよ！
↓↓↓↓
いいですね！クリックするとデバッガーがでってきます! 
メモリや Profiler の画面にちゃんとデーターをレコードできます！残念ながらそれはただ Node.js のコードのためですので R の Implementation とかと比べたいならこのやり方は助かりません。上の visualizer.html または dtrace を使わないといけませんが一応それでパフォーマンス解決についてもう満足しています。
これからは Implementation のパフォマンスをアップするつもりですし、R や emscripten を使って別の Implementation を書くつもりです。進捗について興味があれば martinheidegger/las-2 を Watch してください。質問であればぜひ New Issue を使って聞いてください。
ここまで読んでくれてありがとうございました。
良いお年を！ & Merry Christmas!
Martin Heidegger