search
LoginSignup
2

More than 5 years have passed since last update.

posted at

updated at

Profiling adventure

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

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

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

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

プロセッシングのパーフォマンスを 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.cpuUsageprocess.memoryUsage を使って .stats.csv ファイルに 20 データーポイントを CSV で書き出しています[]。 Gist に置いてある visualizer.html を使うと以下のスクリーショット見たいなグラフが出ています。

Screenshot

このやり方でとりあえず少しでもプロファイルデバッグできるようになりましたがさらに一つのレベルがあります。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 のデベロッパーツールバーに新しいアイコンがありますよ!
テストをスタート前
                          ↓↓↓↓
テストをスタート後


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

デベロッパー画面


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

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

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

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

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
What you can do with signing up
2