Node.js

【JavaScript】 所要時間などを高精度でパフォーマンス計測する方法

更新日：2023/03/27

JavaScriptで処理時間を計測する場合Date.now()でタイムスタンプを取得して差分を求める方法があります。
この方法で得られる精度はミリ秒ですが、もっと高精度な計測が求められるケースもあります。

そこで今回は、JavaScriptで高精度なパフォーマンス計測する方法をお伝えします。

Firefoxの高精度パフォーマンス設定

Firefoxはデフォルトでは高精度のパフォーマンス計測ができません。
次の手順で設定を変えることで、計測が可能になります。

この設定をユーザーに変更してもらうのは、現実的ではないですね。
Webツールなどで高精度なパフォーマンス計測をユーザーに公開するようなケースでは、使用するブラウザを限定する必要がありそうです。

console.time()で手軽に計測

console.time()は、処理時間をフォーマットしてコンソール出力してくれます。

console.time()は、処理時間の計測を開始します。
その際、引数にラベルを指定します。

    // 計測開始
console.time("test");
console.time("test2");

必要に応じて、console.timeLog()を呼び出します。
このメソッドは、console.time()呼び出し後からの途中経過を出力します。

    // 経過時間の表示
console.timeLog("test"); // test: 0.082m
console.timeLog("test2"); // test2: 7.356ms

ミリ秒以下を小数で表示してくれますね。

最後に、console.timeEnd()を呼び出します。
このメソッドも、console.time()呼び出し後からの経過時間を出力します。

    // 終了時間の表示
console.timeEnd("test"); // test: 7.772ms
console.timeEnd("test2"); // test2: 8.286ms

なお、表示されるフォーマットは環境によって異なります。
上記は、Node.jsで出力されたものです。

ブラウザでの出力は、次のようなイメージです。

test: 0.037109375 ms
test2: 0.72509765625 ms
test: 0.79296875 ms
test2: 0.839111328125 ms

test: 0.68ms
test2: 0.42ms
test: 1.1ms - タイマー終了
test2: 1.08ms - タイマー終了

このメソッドは、コンソール出力の準備に時間がかかっている印象です。
特にNode.jsが顕著です。
次の出力例は、最初のNode.js例から抜き出したものです。

console.timeLog("test"); // test: 0.082m
console.timeLog("test2"); // test2: 7.356ms
console.timeEnd("test"); // test: 7.772ms
console.timeEnd("test2"); // test2: 8.286ms

最初のconsole.timeLog()の処理に、約7ミリ秒かかっています。
次のconsole.timeLog()は、1ミリ秒以下です。
この現象は、事前にconsole.log()等を呼び出すことで解消できます。

しかし高精度の計測をするなら、計測そのものの処理はできる限り短時間に収めたいですね。
console.time()は、経過時間の文字列化やコンソール出力など少し重い処理をしているため、高精度計測に向いていないかもしれません。

performance.now()で計測

performance.now()は起点となる時刻からの経過時間をミリ秒単位で取得できます。
その際、ミリ秒よりも小さい値を取得できる場合は小数点以下が使用されます。

起点となる時間は、環境によって異なります。

console.log(  performance.timeOrigin ); // 1644390938451.9

経過時間は、開始および計測タイミングでperformance.now()を呼び出して得た値の差分を求めます。

const start_time = performance.now();
for( let i = 0 ; i < 10000000000 ; i ++);
const end_time = performance.now();
console.log( `処理時間: ${end_time-start_time} ms`); // 処理時間: 12879.58060002327 ms

処理途中のラップ時間も計測するときは、経過時刻を保存しておいて計測終了後に出力します。

  // 経過ログ出力関数
const display_time_log = (label,times)=>
    times.reduce( (start_time , time )=>{
        if( start_time === null ) return time[0];
        console.log( `${label}: ${time[0]-start_time} ms - ${time[1]}`);
        return start_time;
    },null);

const test1_times = [];
const test2_times = [];

    // 計測開始
test1_times.push( [performance.now(),"開始"] );
test2_times.push( [performance.now(),"開始"] );
    // 経過時間の計測
test1_times.push( [performance.now(),"ラップ[1]"] );
test2_times.push( [performance.now(),"ラップ[1]"] );
    // 終了時間の計測
test1_times.push( [performance.now(),"終了"] );
test2_times.push( [performance.now(),"終了"] );

display_time_log("test1",test1_times);
// 結果:
// test1: 0.011699974536895752 ms - ラップ[1]
// test1: 0.01510000228881836 ms - 終了

display_time_log("test2",test2_times);
// 結果:
// test2: 0.003600001335144043 ms - ラップ[1]
// test2: 0.005200028419494629 ms - 終了

performanceの便利なメソッド

performanceオブジェクトのメソッドを使用すると、任意のタイミングで経過時間を名前で記憶したり、記憶した時間毎の差を計測できます。
記憶した情報はperformanceオブジェクトの内部バッファに保存されます。

performanceオブジェクトはインスタンスを生成しないため、常に同じオブジェクトが使用されます。
そのため記憶した情報は、プログラム全体で共有されます。

PerformanceEntryオブジェクト

performanceオブジェクトのメソッドの多くは、次のPerformanceEntryオブジェクトを作成したり取得したりします。

PerformanceEntry{
    name : 名前
    entryType : 記憶されている情報のタイプ "mark"や"measure"など
    startTime : タイムスタンプ
    duration : 間隔
}

このオブジェクトをフォーマットして出力するようなメソッドは用意されていません。
そのため、自作する必要があります。

自作するにはプロパティの確認が必要なため、少し面倒に感じるかもしれません。
performance.now()の結果のみを利用した方が好ましいケースもありますね。

performance.mark()

performance.mark()は引数を一つ受け付け、名前付きで時間を保存します。

performance.mark( name );

引数nameは文字列です。
同じ名前で複数回呼び出すこともできます。

メソッドは、現在の経過時間を記録したPerformanceMarkオブジェクトを生成します。
PerformanceMarkオブジェクトは、次のような形式です。

PerformanceMark{
    name : 引数name
    entryType :  "mark"
    startTime : タイムスタンプ
    duration : 0
}

生成されたPerformanceMarkオブジェクトは、performanceオブジェクトの内部バッファに保管されます。

マークしたオブジェクトは、performance.getEntriesByType("mark")またはperformance.getEntriesByName(name)で取得します。
前者はperformance.mark()で登録したもの全て、後者はnameに一致するものが対象です。

performance.mark("mark1");
performance.mark("mark1");
performance.mark("mark2");

const mark = performance.getEntriesByType("mark");
console.log( mark );
//[
//  PerformanceMark { name: 'mark1', entryType: 'mark', startTime: 38.93539994955063, duration: 0, detail: null},
//  PerformanceMark { name: 'mark1', entryType: 'mark', startTime: 39.125, duration: 0, detail: null },
//  PerformanceMark { name: 'mark2', entryType: 'mark', startTime: 39.13479995727539, duration: 0, detail: null}
//]

const mark1 = performance.getEntriesByName("mark1");
console.log( mark1 );
//[
//  PerformanceMark { name: 'mark1', entryType: 'mark', startTime: 38.93539994955063, duration: 0, detail: null},
//  PerformanceMark { name: 'mark1', entryType: 'mark', startTime: 39.125, duration: 0, detail: null },
//]

performance.measure()

performance.measure()はperformance.mark()の差分を計算します。

performance.measure()は引数を三つ受け付けます。

performance.measure( name  , mark1 , mark2 );

引数は全て文字列です。
mark1とmark2は、performance.mark()で指定した名前と一致する必要があります。

performance.mark()を実行すると、次のような形式でPerformanceMeasureオブジェクトが作成されます。

PerformanceMeasure{
    name : 引数name
    entryType :  "measure"
    startTime : 引数mark1.startTime
    duration : 引数mark2.startTime - 引数mark1.startTime
}

performance.mark()で複数の同名マークをセットしている場合は、最後のエントリが使用されます。

performance.mark()の結果は、performance.getEntriesByType("measure")で取得します。

performance.mark("mark1");
performance.mark("mark1");
performance.mark("mark2");
performance.mark("mark1");
performance.mark("mark2");

performance.measure("test1","mark1","mark2");

console.log(performance.getEntriesByType("measure"));
//[
//  PerformanceMeasure {
//    name: 'test1',
//    entryType: 'measure',
//    startTime: 37.6385999917984,
//    duration: 0.00270003080368042,
//    detail: null
//  }
//]

  // 補足確認：計算に使用されたプロパティ
console.log(
    performance.getEntriesByName("mark1")[2].startTime,
    performance.getEntriesByName("mark2")[1].startTime 
      - performance.getEntriesByName("mark1")[2].startTime
    );
// 37.6385999917984 0.00270003080368042

performance.getEntries()

performance.getEntries()は、登録されているPerformanceEntryオブジェクトを配列で取得します。
引数はありません。

performance.mark("start");
waitFunc();
performance.mark("end");
performance.measure("総時間", "start", "end");

performance.getEntries().forEach(
    e=>console.log( e )
)

結果は次のようになります。

0 PerformanceNavigationTiming { name: "document", entryType: "navigation", startTime: 0, duration: 131 }
1 PerformanceMark { name: "test", entryType: "mark", startTime: 82, duration: 0 }
2 PerformanceMark { name: "start", entryType: "mark", startTime: 83, duration: 0 }
3 PerformanceMeasure { name: "総時間", entryType: "measure", startTime: 83, duration: 1 }
4 PerformanceMark { name: "end", entryType: "mark", startTime: 84, duration: 0 }

要素の並び順は、startTimeでソートされています。
markなどのメソッドを実行した順番ではありません。

登録のクリア

performance.mark()とperformance.measure()で登録したデータが保存されるオブジェクトはグローバルなため、自動的に削除されません。

そのため、必要に応じて削除します。
それぞれ対応する削除メソッドがあります。

performance.mark()の削除メソッド

performance.clearMarks(name)

nameを省略すると、全てのマークオブジェクトが削除されます。

performance.measure()の削除メソッド

performance.clearMeasures(name)

nameを省略すると、全てのメジャーオブジェクトが削除されます。

関連記事

スポンサーリンク

記事の内容について

こんにちはけーちゃんです。
説明するのって難しいですね。

「なんか言ってることおかしくない？」
たぶん、こんなご意見あると思います。

裏付けを取りながら記事を作成していますが、僕の勘違いだったり、そもそも情報源の内容が間違えていたりで、正確でないことが多いと思います。
そんなときは、ご意見もらえたら嬉しいです。

掲載コードについては事前に動作確認をしていますが、貼り付け後に体裁を整えるなどをした結果動作しないものになっていることがあります。
生暖かい視線でスルーするか、ご指摘ください。

ご意見、ご指摘はこちら。
https://note.affi-sapo-sv.com/info.php

 

このサイトは、リンクフリーです。大歓迎です。