前回の記事とはまた別の話です。
今回は、土曜日に京都で話したきたPerformance Timing APIについて話します。
特別になりたい山
特別になりたい川
本題ですが、Performance Timing APIは、Stability1に属します。
ドキュメントはこちらです。
Performance Timing API | Node.js v9.9.0 Documentation
現在のNode.jsの安定性指標
Node.jsには各モジュール・メソッドにStability(安定性)の指標があり、0 - 2の3種類があります。
- 0: Depricated(非推奨)
- 1: Experimental(実験的)
- 2: Stable(安定)
現在、Node9の段階で、Stability1は以下のとおりです。
現在のNode.jsのStability1(実験的)は以下のAPI
— hiroppy😶 (@about_hiroppy) 2018年3月23日
- vm.Module
- N-API
- readable[@@asyncIterator] (Readable Streams)
- HTTP2
- ECMAScript Modules
- Inspector
- fs Promises API
- Serialization API(V8)
- Async Hooks
- perf_hooks
- Errorsの一部
Performance Timing API
8.5.0から入ったAPIで、W3C Performance Timeline
の仕様実装となります。
また、現在、ブラウザに実装されているPerformance APIと同等です。
過去に書いた上記の記事が最初に入った時です。
このときは、processに入っていましたが、今現在ではperf_hooksのモジュール内に入ることになりました。
また、APIの変更が多いので今となってはあまり参考にならなくなってしまった記事な気がします。
このようにStability1というのはまだ不安定です。
目的
正確な実測値を知ることにより、パフォーマンスの改善の手助けを行います。
Performance Timing APIでは大まかに以下の2種類の測定が行えます。
- 区間にかかる時間測定
- イベントにかかる測定
提供される変数・メソッド
今現在、提供されているAPIは以下のとおりです。
const { constants, performance, performanceObserver } = require('perf_hooks');
constants: 変数が入っています(現在はGC周りのみ)performance: パフォーマンス周りのAPIを提供しますperformanceObserver: パフォーマンスタイムラインを監視します
イメージ
Performance Timeline | Entry |
Observer | User | System |
|
| <------------------------------ <node>
| <---------------- <mark>
|
| <------------------------------ <gc>
|
| <---------------- <mark>
|
| <---------------- <measure>
|
| <---------------- <function>
|
| <------------------------------ <http2>
|
|
このように、パフォーマンスタイムラインという軸に対して、エントリをセットしていきます。
タイムラインに入る個数はデフォルトで150個であり、超えるとプロセスの警告がでます。
エントリには二種類あり、使用者が設置するエントリーとNode側が設置するエントリーが存在します。
PerformanceEntry
エントリのクラスです。
インターナルのクラスなのでユーザが明示的に使うことはないです。
基本的には以下のプロパティを持ちます。
name, duration, startTime, entryType
nodeのみPerformanceEntryを継承したPerformanceNodeTimingとなります。
entryType
entryの種類は今の所6種類です。
- ユーザ側
- mark
- measure
- function
- システム側
- node
- gc
- http2
node
nodeは起動時等にシステム側が差し込むエントリです。
nodeの起動時に遅かったりしたらこちらを確認するといいと思います。
{ name: 'node', entryType: 'node', startTime: 0, duration: 217.51575499773026, nodeStart: 30.049373984336853, v8Start: 42.87327700853348, bootstrapComplete: -1, environment: 71.10232901573181, loopStart: -1, loopExit: -1, thirdPartyMainStart: -1, thirdPartyMainEnd: -1, clusterSetupStart: -1, clusterSetupEnd: -1, moduleLoadStart: 174.59000700712204, moduleLoadEnd: 174.6149640083313, preloadModuleLoadStart: 174.61514300107956, preloadModuleLoadEnd: 174.65145403146744 }
このように、nodeが開始された時間やV8プラットフォームが初期化された時間、モジュールのロード開始、終了した時間等が記載されます。
gc
GCが発生した時に、システム側が差し込むエントリです。
[ PerformanceEntry { name: 'gc', entryType: 'gc', startTime: 160.643631, duration: 0.464252, kind: 1 } ]
gcの特徴としては、kindが数値なとこです。
これを知るためには、constants と照らし合わせる必要があります。
const { constants } = require('perf_hooks'); console.log(constants); { NODE_PERFORMANCE_GC_MAJOR: 2, NODE_PERFORMANCE_GC_MINOR: 1, NODE_PERFORMANCE_GC_INCREMENTAL: 4, NODE_PERFORMANCE_GC_WEAKCB: 8 }
今回の場合、kindが1なので、minor GCということがわかります。
Performance
主要なものだけ。
timeOrigin
現在のnodeプロセス開始時のunix timeのミリ秒のタイムスタンプを返します。
now()
nodeプロセスの開始地点からの現在のミリ秒のタイムスタンプを返します。
nodeTiming
nodeentry(PerformanceNodeTiming class)の値を返します。
mark()
パフォーマンスタイムラインに新しいmarkエントリを追加します。
あくまでも、地点であり区間ではないので、durationは必ず0です。
measure()
パフォーマンスタイムラインに新しいmeasureエントリを追加します。
開始地点と終了地点を指定し、名前を付けます。
この名前は、そのmeasureエントリの名前(performanceEntry.name)となります。
durationはそのmarkの開始から終了までの経過した時間のミリ秒です。
timerify()
functionエントリでラップした関数を返します。
getEntries()
時系列順にすべてのパフォーマンスタイムラインに入っているエントリを返します。
getEntriesByName() / getEntriesByType()
名前やタイプを指定すると条件にあったエントリを返します。
PerformanceObserver
パフォーマンスタイムラインにエントリが入った時に通知する役割を持ちます。
const { performance, PerformanceObserver } = require('perf_hooks'); // ここのコールバックに通知が行く const obs = new PerformanceObserver((list, observer) => { // パフォーマンスタイムラインの指定したエントリのタイプのすべてを取得する console.log(list.getEntries()); // 要らなくなったら切りましょう observer.disconnect(); }); // 監視を開始する // 監視したいエントリーを指定する(配列に複数可能) // entryTypes: 'mark' | 'measure' | 'function' | 'gc' | 'http2' | 'node' obs.observe({ entryTypes: ['mark'], buffered: true }); // markしてみる performance.mark('test');
このように、様々なイベントの情報をここでとることが可能です。
また、gcやhttp2の状況が知りたいという時にももちろん使えます。
const { PerformanceObserver } = require('perf_hooks'); let str = ''; for(let i = 0; i< 10000; i++) { str += `${i}`; } console.log(str); const obs = new PerformanceObserver((list, observer) => { console.log(list.getEntries()); /* [ PerformanceEntry { name: 'gc', entryType: 'gc', startTime: 304648089.396532, duration: 0.860463, kind: 1 }, PerformanceEntry { name: 'gc', entryType: 'gc', startTime: 304648097.950489, duration: 1.2521, kind: 1 }, PerformanceEntry { name: 'gc', entryType: 'gc', startTime: 304648128.501536, duration: 0.704473, kind: 1 } ] */ observer.disconnect(); }); obs.observe({ entryTypes: ['gc'], buffered: true });
つまり、Performance Timing APIでは、自分でマーキングする方法と、イベントを監視する方法の2種類があることがわかります。
ユーザーの手順
ユーザーが使えるエントリは、mark, measure, functionの3種類となります。
区間測定を行う
// <---- A foo(); bar(); // <---- B
例えば、AからBの到達までにかかる時間を測定したい場合です。
ここでは、markとmeasureを使い、以下の手順を行います。
mark: 開始地点をマークする(上の例だとA)mark: 終了地点をマークする(上の例だとB)measure: 1, 2で定義したマークの区間に名前をつけるgetEntriesByName: タイムラインから3で定義した名前で検索する
const { readFileSync } = require('fs'); const { performance } = require('perf_hooks'); performance.mark('A'); // 1 readFileSync('./node'); // nodeの読み込み時間を計測したい performance.mark('B'); // 2 performance.measure('A to B', 'A', 'B'); // 3. 'A'と'B'の区間を'A to B'という名前で定義する const measure = performance.getEntriesByName('A to B'); // 4. 3で定義した名前で検索する console.log(measure); [ PerformanceEntry { name: 'A to B', entryType: 'measure', startTime: 87.395975, duration: 24.579894 } ]
関数実行にかかる時間を測定する
この場合、performance.timerifyを使い、function エントリにラップされた関数を作ります。
また、PerformanceObserverを使い、実行されたら確認することが可能です。
const { performance, PerformanceObserver } = require('perf_hooks'); function create() { // この関数の開始時間、処理にかかった時間を調べたい console.log('create'); } // パフォーマンスタイムラインの監視をする const obs = new PerformanceObserver((list, observer) => { console.log(list.getEntries()); /* [ PerformanceEntry { name: 'create', // 関数名 entryType: 'function', startTime: 303589235.120023, // 開始時間 duration: 1.286037 } ] // かかった時間 */ observer.disconnect(); }); // 今回は、entryの種類が'function'なので、'function'を指定する obs.observe({ entryTypes: ['function'], buffered: true }); // `performance.timerify`を使い、`wrapped`という名前で`function`のエントリータイプを作成 const wrapped = performance.timerify(create); // 実行すると、obsのインスタンス化した時に指定したコールバックに情報が入る wrapped();
使用例
Server Side Rendering
実行時間が測れるので、例えばReact.renderToString()にどれぐらいかかっているかを調べることが可能です。
const { performance, PerformanceObserver } = require('perf_hooks'); const React = require('react'); const { renderToString } = require('react-dom/server'); // renderToStringをwatchする const render = performance.timerify(renderToString); const obs = new PerformanceObserver((list, observer) => { const data = list.getEntries(); data.forEach((l) => { if (l.name === 'renderToString') console.log('duration', l.duration); }); observer.disconnect(); }); obs.observe({ entryTypes: ['function'], buffered: true }); const Main = (props) => { return React.createElement( 'li', null, [...new Array(props.n)].map((_, i) => { return React.createElement('li', {key: i}, 'test'); }) ); }; render(Main(1)); render(Main(100)); render(Main(10000)); render(Main(1000000));
measureもそうですが、同じ関数の場合はスタックされていくので、後ろの実行分が先にでます。
出力は以下のようになります。
$ node index.js duration 2.574169ms duration 0.132851ms duration 0.06978ms duration 0.066551ms
このようにつかうことにより、どこが障害点なのかがわかりやすく、チューニングの手助けになると思います。
まとめ
測定を行うことにより、アプリケーションのボトルネックを見つけ、チューニングをしやすくします。
区間測定をしたい場合
開始地点と終了地点をmarkして、measureで区間の名前を付ける。
イベントの測定をしたい場合
PerformanceObserverを使い監視する。
もし、その関数の実行時間等が知りたければperformance.timerifyを通す。
