プロファイリング・コマンドライン・ツール

GraalVMプロファイリング・コマンドライン・ツールは、CPU使用率およびメモリー使用量を分析してコードを最適化するために役立ちます。

ほとんどのアプリケーションでは、コードの20%でランタイムの80%が費やされます。このため、コードを最適化するには、アプリケーションが時間を費やしている場所を把握することが不可欠です。この項では、サンプル・アプリケーションを使用して、GraalVMが提供するCPUトレーサ、CPUサンプラおよびメモリー・トレーサの3つの主要なプロファイリング機能について説明します。

このサンプル・アプリケーションでは、エラトステネスのふるいアルゴリズムに基づいた基本的な素数計算機を使用します。

  1. 次のコードをprimes.jsという名前の新しいファイルにコピーします:

     class AcceptFilter {
     accept(n) {
         return true
     }
 }

 class DivisibleByFilter {
     constructor(number, next) {
         this.number = number;
         this.next = next;
     }

     accept(n) {
         var filter = this;
         while (filter != null) {
             if (n % filter.number === 0) {
                 return false;
             }
             filter = filter.next;
         }
         return true;
     }
 }

 class Primes {
     constructor() {
         this.number = 2;
         this.filter = new AcceptFilter();
     }

     next() {
         while (!this.filter.accept(this.number)) {
             this.number++;
         }
         this.filter = new DivisibleByFilter(this.number, this.filter);
         return this.number;
     }
 }

 var primes = new Primes();
 var primesArray = [];
 for (let i = 0; i < 5000; i++) {
     primesArray.push(primes.next());
 }
 console.log(`Computed ${primesArray.length} prime numbers. ` +
             `The last 5 are ${primesArray.slice(-5)}.`);
  2. js primes.jsを実行します。このサンプル・アプリケーションによって次のように出力されます: 
     js primes.js
 Computed 5000 prime numbers. The last 5 are 48563,48571,48589,48593,48611.

    このプログラムの計算には少し時間がかかります。次に、時間がどこで費やされたかを確認します。

  3. js --cpusampler primes.jsを実行して、CPUサンプリングを有効にします。サンプル・アプリケーションの出力は、CPUサンプラによって次のように出力されます: 
     js --cpusampler primes.js

 Computed 5000 prime numbers. The last 5 are 48563,48571,48589,48593,48611.
 ----------------------------------------------------------------------------------------------
 Sampling Histogram. Recorded 250 samples with period 10ms.
   Self Time: Time spent on the top of the stack.
   Total Time: Time spent somewhere on the stack.
 ----------------------------------------------------------------------------------------------
 Thread[main,5,main]
  Name       ||             Total Time    ||              Self Time    || Location
 ----------------------------------------------------------------------------------------------
  accept     ||             2150ms  86.0% ||             2150ms  86.0% || primes.js~13-22:191-419
  next       ||             2470ms  98.8% ||              320ms  12.8% || primes.js~31-37:537-737
  :program   ||             2500ms 100.0% ||               30ms   1.2% || primes.js~1-46:0-982
 ----------------------------------------------------------------------------------------------

    デフォルトでは、サンプラにより、JavaScript関数ごとに実行時間のヒストグラムが出力されます。

    --cpusampler=flamegraphオプションを指定して要求すると、SVG形式のフレーム・グラフを生成できます:

     js --cpusampler=flamegraph primes.js

    次のような内容のflamegraph.svgというファイルが生成されます:

    要素をクリックすると、グラフにズームインできます。

    デフォルトでは、CPUサンプリングは10ミリ秒ごとにサンプルを取得します。結果から、DivisibleByFilter.accept関数で約89%の時間が費やされていることがわかります。

     accept(n) {
     var filter = this;
     while (filter != null) {
         if (n % filter.number === 0) {
             return false;
         }
         filter = filter.next;
     }
     return true;
 }

    詳細は、このブログ投稿を参照してください。

    ここで、CPUトレーサを使用して、各文の実行数を収集します:

  4. js primes.js --cputracer --cputracer.TraceStatements --cputracer.FilterRootName=*acceptを実行して、acceptで終わるメソッド内のすべての文の実行数を収集します: 
     js primes.js --cputracer --cputracer.TraceStatements --cputracer.FilterRootName=accept
 Computed 5000 prime numbers. The last 5 are 48563,48571,48589,48593,48611.
 -----------------------------------------------------------------------------------------
 Tracing Histogram. Counted a total of 468336895 element executions.
   Total Count: Number of times the element was executed and percentage of total executions.
   Interpreted Count: Number of times the element was interpreted and percentage of total executions of this element.
   Compiled Count: Number of times the compiled element was executed and percentage of total executions of this element.
 -----------------------------------------------------------------------------------------
  Name     |          Total Count |    Interpreted Count |       Compiled Count | Location
 -----------------------------------------------------------------------------------------
  accept   |     234117338  50.0% |        365660   0.2% |     233751678  99.8% | primes.js~15:245-258
  accept   |     117053670  25.0% |        182582   0.2% |     116871088  99.8% | primes.js~16-18:275-348
  accept   |     117005061  25.0% |        181001   0.2% |     116824060  99.8% | primes.js~19:362-381
  accept   |         53608   0.0% |          1829   3.4% |         51779  96.6% | primes.js~14:211-227
  accept   |         53608   0.0% |          1829   3.4% |         51779  96.6% | primes.js~13-22:191-419
  accept   |         48609   0.0% |          1581   3.3% |         47028  96.7% | primes.js~17:322-334
  accept   |          4999   0.0% |           248   5.0% |          4751  95.0% | primes.js~21:402-413
  accept   |             1   0.0% |             1 100.0% |             0   0.0% | primes.js~2-4:25-61
  accept   |             1   0.0% |             1 100.0% |             0   0.0% | primes.js~3:45-55
 -----------------------------------------------------------------------------------------

    出力には、タイミング情報ではなく、各文の実行カウンタが表示されます。多くの場合、ヒストグラムをトレースすることで、最適化が必要なアルゴリズムの動作に関するインサイトが提供されます。

  5. js primes.js --experimental-options --memtracerを実行して、ソース・コードの場所およびレポートされた割当ての数を表示します。割当てを取得するためのメモリー・トレーサ・ツールは、現在、GraalVMの試験段階の機能であることに注意してください。したがって、--memtracerの前に--experimental-optionsコマンドライン・オプションを付ける必要があります。 
     js primes.js --experimental-options --memtracer
 Computed 5000 prime numbers. The last 5 are 48563,48571,48589,48593,48611.
 ------------------------------------------------------------
 Location Histogram with Allocation Counts. Recorded a total of 5007 allocations.
   Total Count: Number of allocations during the execution of this element.
   Self Count: Number of allocations in this element alone (excluding sub calls).
--------------------------------------------------------
 Name     |      Self Count |     Total Count | Location
--------------------------------------------------------
 next     |     5000  99.9% |     5000  99.9% | primes.js~31-37:537-737
 :program |        6   0.1% |     5007 100.0% | primes.js~1-46:0-982
 Primes   |        1   0.0% |        1   0.0% | primes.js~25-38:424-739
--------------------------------------------------------

    この出力には、関数ごとに記録された割当ての数が表示されます。計算された素数ごとに、プログラムにより、DivisibleByFilterのnextおよびconstructorに、それぞれ1つのオブジェクトが割り当てられます。割当ては、コンパイラによって削除できるかどうかに関係なく記録されます。

    GraalVMコンパイラは、特に割当ての最適化に優れ、実行パフォーマンスを改善するために、割当てを頻度の低いブランチにプッシュできます。GraalVMチームは、将来、メモリーの最適化に関する情報をメモリー・トレーサに追加する予定です。

ツール・オプション

CPUサンプラ、CPUトレーサおよびメモリー・トレーサの参照情報を表示するには、すべてのゲスト言語ランチャで--help:toolsオプションを使用します。現在使用可能な一連のオプションは次のとおりです

CPUサンプラ・オプション

CPUトレーサ・オプション

メモリー・トレーサ・オプション

メモリー・トレーサ・ツールは、現在試験段階のツールです。--memtracerを有効にするには、必ず--experimental-optionsフラグを先頭に追加してください。