原文はこちら。
The original article was written by Boris Spasojević (Principal Researcher at Oracle).
https://medium.com/graalvm/where-has-all-my-run-time-gone-245f0ccde853
Introduction
開発者は、常にアプリケーションのパフォーマンスを向上させたいと考えています。通常、このプロセスの最初のステップは、アプリケーションのパフォーマンス特性を理解することであり、そのための最も一般的なツールがCPU Samplerです。一般的にCPU Samplerは、実行中のアプリケーションを観察し、定期的にコールスタックのスナップショットを取り、このデータをまとめて、アプリケーションのどの部分にどれだけの時間が費やされたかを概算します（特定の関数がコールスタック上で何度も見られるほど、アプリケーションの実行時間がその特定の関数に費やされたことになります）。
GraalVMには、Truffleフレームワークで構築された全ての言語に対応したCPU Samplerが内蔵されています。このCPU Samplerは、完全に言語非依存で、Truffle APIを使用して構築されたサードパーティの言語実装や、実行中にTruffle言語が組み合わされるPolyglot環境でも動作します。
21.3.0のリリースでは、このCPU Samplerが大幅に改良されました。これ以後で、CPU Samplerの機能と、改良で導入された改善点を紹介します。
An Example
ここでは、primes.jsというファイルに格納されている小さなJavaScriptアプリケーションを例に考えてみましょう。
| // Naive prime calculator | |
| function isPrime(x) { | |
| for (i = 2; i < x; i++) { | |
| if (x % i == 0) { | |
| return false | |
| } | |
| } | |
| return true | |
| } | |
| function findPrime(i) { | |
| prime=1; | |
| do { | |
| prime=prime + 1; | |
| if (isPrime(prime)) { | |
| i--; | |
| } | |
| } while(i > 0); | |
| return prime | |
| } | |
| // Prime number calculator based on the Sieve of Eratosthenes algorithm. | |
| class AcceptFilter { | |
| accept(n) { | |
| return true | |
| } | |
| } | |
| class DivisibleByFilter { | |
| constructor(number, next) { | |
| this.number = number; | |
| this.next = next; | |
| } | |
| accept(n) { | |
| var filter = this; | |
| // if (filter != null) { | |
| while (filter != null) { | |
| if (n % filter.number === 0) { | |
| return false; | |
| } | |
| // return filter.next.accept(n); | |
| 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; | |
| } | |
| } | |
| // Verify results are the same | |
| var primes = new Primes(); | |
| for (let i = 1; i <= 1000; i++) { | |
| sievePrive = primes.next() | |
| naivePrime = findPrime(i) | |
| if (naivePrime != sievePrive || !isPrime(sievePrive)) { | |
| throw "Error!" + i | |
| } | |
| } | |
| console.log('OK') |
このアプリケーションは、素数を計算するための2つのアプローチを使い、最初の1000個の素数について同じ結果になることを検証します。1つは、連続する各数字に約数があるかどうかをチェックするという、完全に素朴なアプローチで、もう1つは「エラトステネスの篩い」のアルゴリズムに基づきます。
エラストテネスの篩い / Sieve of Eratosthenes
https://ja.wikipedia.org/wiki/%E3%82%A8%E3%83%A9%E3%83%88%E3%82%B9%E3%83%86%E3%83%8D%E3%82%B9%E3%81%AE%E7%AF%A9
https://en.wikipedia.org/wiki/Sieve_of_Eratosthenes
CPU Samplerを使って、実行時間がどのように費やされているかを概観してみましょう。
CPU Samplerには、実行のプロファイルを出力するいくつかの方法があります。便利な出発点にしてデフォルトの出力は、CLIで出力されるヒストグラム・ビューです。21.3.0のリリースでは、一般的なユースケースを考慮してこのビューが簡素化され、詳細をより深く掘り下げるためのより複雑なオプションが追加されました。
次の図は、実行中の例のデフォルトのヒストグラム出力です。
| $GRAALVM_HOME/bin/js --cpusampler primes.js | |
| ------------------------------------------------------------------------------------------------ | |
| Sampling Histogram. Recorded 774 samples with period 10ms. Missed 1 samples. | |
| 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 | |
| ------------------------------------------------------------------------------------------------ | |
| isPrime || 7330ms 94.7% || 7330ms 94.7% || primes.js~2-9:26-161 | |
| accept || 330ms 4.3% || 330ms 4.3% || primes.js~35-46:596-902 | |
| findPrime || 7370ms 95.2% || 70ms 0.9% || primes.js~11-20:164-329 | |
| AcceptFilter || 10ms 0.1% || 10ms 0.1% || primes.js~23-27:405-468 | |
| Primes || 10ms 0.1% || 0ms 0.0% || primes.js~49-62:907-1222 | |
| next || 330ms 4.3% || 0ms 0.0% || primes.js~55-61:1020-1220 | |
| :program || 7740ms 100.0% || 0ms 0.0% || primes.js~1-73:0-1488 | |
| ----------------------------------------------------------------------------------------------- |
Total Time（合計時間）の欄を見ると、すべての呼び出しを含めて、各関数にどれだけの時間がかかったかがわかります。素朴な素数計算機であるfindPrimeでは95%以上の時間を費やし、エラトステネスのふるいアプローチであるnextでは、わずか4.3%しか費やしていないことがわかります。これらの関数はどちらも同じこと、つまり素数を計算することを目的としているので、「エラトステネスのふるい」アルゴリズムに基づくアプローチは、素朴なものに比べて20倍以上効率的であると結論づけることができます。Self Time（個々の時間）の欄には、個々の関数が実行時間のどの割合を占めたかが表示されています。実行時間のほとんどすべてがisPrime関数に費やされています。なぜこの1つの関数に多くの時間を費やしているのかを理解することが、このプログラムのパフォーマンス向上の鍵です。
ソースコードを見ると、isPrime関数が2箇所で呼び出されていることがわかります。1つは素朴な方法で素数を求めるため（15行目）、もう1つは素数計算機が実際に素数を生成することを検証するため（69行目）です。実行時間のほとんどがこの関数に費やされているので、これらの呼び出しサイトが実行時間の使用にどれだけ貢献しているかを知るのは有益と思われます。このためには、CPU Sampler のコールツリー出力を使用します。
| $GRAALVM_HOME/bin/js --cpusampler --cpusampler.Output=calltree primes.js | |
| ---------------------------------------------------------------------------------------------- | |
| Sampling Call Tree. Recorded 780 samples with period 10ms. Missed 0 samples. | |
| Self Time: Time spent on the top of the stack. | |
| Total Time: Time spent somewhere on the stack. | |
| ---------------------------------------------------------------------------------------------- | |
| Name || Total Time || Self Time || Location | |
| ---------------------------------------------------------------------------------------------- | |
| :program || 7800ms 100.0% || 0ms 0.0% || primes.js~1-73:0-1488 | |
| findPrime || 7440ms 95.4% || 40ms 0.5% || primes.js~11-20:164-329 | |
| isPrime || 7400ms 94.9% || 7400ms 94.9% || primes.js~2-9:26-161 | |
| next || 320ms 4.1% || 0ms 0.0% || primes.js~55-61:1020-1220 | |
| accept || 320ms 4.1% || 320ms 4.1% || primes.js~35-46:596-902 | |
| isPrime || 40ms 0.5% || 40ms 0.5% || primes.js~2-9:26-161 | |
| ---------------------------------------------------------------------------------------------- |
この表示では、各エントリは集約された機能情報ではなく、コールサイトを表しています。Name列のインデントは、出力のツリー構造をエンコードしています。findPrime関数からのisPrimeへの呼び出しで実行時間の大部分が消費されており、:programからの呼び出しは無視できることがわかります。
findPrime関数を調べてみると、i番目の素数を計算していることがわかります。一方、エラストテネスの篩いのアプローチでは、最後の素数をキャッシュし、次の素数のみを計算します。最初の1000個の素数を順に比較すると、両者のアプローチにはかなりの差があり、エラストテネスの篩いのアプローチが非常に有利であることがわかります。findPrime関数が最後の素数の値を取って次の素数を見つけるよう元のソースを修正すると、より公平な競争になります。この修正版をprimes-opt.jsと呼ぶことにし、そのバージョンのCPU Samplerヒストグラムを見てみましょう。
| // Naive prime calculator | |
| function isPrime(x) { | |
| for (i = 2; i < x; i++) { | |
| if (x % i == 0) { | |
| return false | |
| } | |
| } | |
| return true | |
| } | |
| function findPrime(i) { | |
| prime = i; | |
| do { | |
| prime = prime + 1; | |
| if (isPrime(prime)) { | |
| return prime; | |
| } | |
| } while (true); | |
| } | |
| // Prime number calculator based on the Sieve of Eratosthenes algorithm. | |
| class AcceptFilter { | |
| accept(n) { | |
| return true | |
| } | |
| } | |
| class DivisibleByFilter { | |
| constructor(number, next) { | |
| this.number = number; | |
| this.next = next; | |
| } | |
| accept(n) { | |
| var filter = this; | |
| // if (filter != null) { | |
| while (filter != null) { | |
| if (n % filter.number === 0) { | |
| return false; | |
| } | |
| // return filter.next.accept(n); | |
| 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; | |
| } | |
| } | |
| // Verify results are the same | |
| var primes = new Primes(); | |
| var lastPrime = 1; | |
| for (let i = 1; i <= 1000; i++) { | |
| sievePrive = primes.next() | |
| naivePrime = findPrime(lastPrime) | |
| lastPrime = naivePrime | |
| if (naivePrime != sievePrive || !isPrime(sievePrive)) { | |
| throw "Error!" + i | |
| } | |
| } | |
| console.log('OK') |
| $GRAALVM_HOME/bin/js --cpusampler primes-opt.js | |
| ---------------------------------------------------------------------------------------------- | |
| Sampling Histogram. Recorded 40 samples with period 10ms. Missed 0 samples. | |
| 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 || 340ms 85.0% || 340ms 85.0% || primes-opt.js~34-45:592-898 | |
| isPrime || 60ms 15.0% || 60ms 15.0% || primes-opt.js~2-9:26-161 | |
| next || 340ms 85.0% || 0ms 0.0% || primes-opt.js~54-60:1016-1216 | |
| :program || 400ms 100.0% || 0ms 0.0% || primes-opt.js~1-74:0-1540 | |
| findPrime || 30ms 7.5% || 0ms 0.0% || primes-opt.js~11-19:164-325 | |
| ---------------------------------------------------------------------------------------------- |
この変更はアプリケーション全体の実行時間に非常に大きな影響を与えており、isPrimeで費やされる時間は約7秒から約60ミリ秒に短縮していることがわかります。合計時間を見ると、findPrime関数がわずか7.5%であるのに対し、エラストテネスの篩いアプローチのnext関数が実行時間の85%を占めていることがわかります。つまり、同じ条件であれば、初歩的なアプローチの方が10倍以上速いということです。この理由については、読者の皆様への宿題にしたいと思います。（原文の）コメントで教えてください。
A More Interactive Visualization
これまで見てきたCLI出力は便利ですが、少し静的で、視覚的ではありませんでした。特に大規模なアプリケーション向けではないですね。CPU Samplerは、生データをjsonファイルとして吐き出すオプションを提供しており、これにより無限の処理と可視化のオプションが可能になりますが、このためには追加の労力が必要です。GraalVM 21.3.0では、Duncan MacGregorがCPU Samplerの新しい出力モードとしてフレームグラフを導入しました。このモードで出力すると、一般的なプロファイルの可視化である、視覚的でインタラクティブなフレームグラフを含むSVGファイルを生成します。
Duncan MacGregor
https://github.com/aardvark179
フレームグラフは、基本的にコールツリーを重ねて表現したものです。
つまり、各エントリの幅は、その下のエントリである呼び出し元に対して、その関数にどれだけの時間が費やされたかを表しています。これは、以前に見たコールツリーの出力に似ています。コールサイト固有のカウントが表示されるため、特定のコールサイトでより多くの時間が費やされているかどうかがわかります。利便性のため、可視化にはフレームグラフの下にヒストグラム表示も含まれています。コマンドラインに
--cpusampler --cpusampler.Output=flamegraph --cpusampler.OutputFile=profile.svg
を追加すれば、実行結果のフレームグラフを得ることができます。
以下は、Ruby のベンチマークである Optcarrot のフレームグラフです。
下図は有名なRubyのベンチマークOptcarrotで生成したフレームグラフです。
このファイルをブラウザで開いて、インタラクティブな部分を確認ください。この可視化では、個々の関数にズームインしたり、関数、コンパイル情報、言語情報を示す3つの異なるカラースキームを循環させたりできます。
VisualVM and Chrome Inspector Integration
CPU SamplerはAPIを提供しており、他のGraalVMツールがこのAPIを利用して、APIがもたらすデータを他のアプリケーションに公開できます。そのような例を2つ挙げるとすれば、以下のスクリーンショットに示すように、VisualVMおよびChrome inspectorとの統合があります。これらのツールはいずれも、統合されたCPU Samplerを活用してプロファイルを取得し、エンドユーザーに親しみやすい方法で表示します。これにより、エンドユーザーの選択肢が増えるだけでなく、CPU Samplerというデータ収集のコアが共有されているため、そのコアが改良されれば、暗黙のうちにこれらのツールも改良されることにつながります。
The Impact of the JIT
JITコンパイルされた言語を使用しているため、JITコンパイラがパフォーマンスに与える影響について、例えばどの関数がコンパイルされたか、コンパイルされたコードにどれだけの時間が費やされたか、などの疑問を考慮する必要があるかもしれません。GraalVM 21.1.0では、Truffle言語の多層コンパイルが導入されたため、「ある関数がどのコンパイル階層でコンパイルされたか」を確認することもできます。これらの問いの回答は、最初の例のコマンドラインに
--cpusampler.ShowTiers=true
を追加することです。これにより、以下のような出力が得られます。
| $GRAALVM_HOME/bin/js --cpusampler --cpusampler.ShowTiers=true primes.js | |
| ----------------------------------------------------------------------------------------------------------------------------------------------------------- | |
| Sampling Histogram. Recorded 780 samples with period 10ms. Missed 0 samples. | |
| Self Time: Time spent on the top of the stack. | |
| Total Time: Time spent somewhere on the stack. | |
| T0: Percent of time spent in interpreter. | |
| T1: Percent of time spent in code compiled by tier 1 compiler. | |
| T2: Percent of time spent in code compiled by tier 2 compiler. | |
| ----------------------------------------------------------------------------------------------------------------------------------------------------------- | |
| Thread[main,5,main] | |
| Name || Total Time | T0 | T1 | T2 || Self Time | T0 | T1 | T2 || Location | |
| ----------------------------------------------------------------------------------------------------------------------------------------------------------- | |
| isPrime || 7280ms 93.3% | 0.7% | 0.5% | 98.8% || 7280ms 93.3% | 0.7% | 0.5% | 98.8% || primes.js~2-9:26-161 | |
| accept || 500ms 6.4% | 2.0% | 0.0% | 98.0% || 500ms 6.4% | 2.0% | 0.0% | 98.0% || primes.js~35-46:596-902 | |
| DivisibleByFilter || 10ms 0.1% | 100.0% | 0.0% | 0.0% || 10ms 0.1% | 100.0% | 0.0% | 0.0% || primes.js~29-47:471-904 | |
| findPrime || 7260ms 93.1% | 0.6% | 1.1% | 98.3% || 10ms 0.1% | 0.0% | 0.0% | 100.0% || primes.js~11-20:164-329 | |
| next || 510ms 6.5% | 5.9% | 3.9% | 90.2% || 0ms 0.0% | 0.0% | 0.0% | 0.0% || primes.js~55-61:1020-1220 | |
| :program || 7800ms 100.0% | 100.0% | 0.0% | 0.0% || 0ms 0.0% | 0.0% | 0.0% | 0.0% || primes.js~1-73:0-1488 | |
| ---------------------------------------------------------------------------------------------------------------------------------------------------------- |
この出力は、各関数がどのコンパイル階層にてどれだけの時間を費やしたかを示しています。このケースでは、影響の大きい関数のほとんど（98％以上）が、最高レベルの最適化を施したTier2コンパイラでコンパイルされたコードで実行されていることがわかります。
Under the Hood
GraalVMの21.3.0リリース以前のCPU Samplerは、Truffle instrumentation frameworkを用いて実装されており、プログラムの実行中にシャドー・スタックを保持し、定期的にシャドー・スタックをサンプリングしてコール・スタック・データを収集することで動作していました。これはCPU Samplerの実装としては単純なものでしたが、オーバーヘッドという大きな欠点がありました。シャドー・スタックを最新の状態に保つことは、関数の呼び出しと終了のたびに追加のスタック・データ構造を操作することを意味し、大きなオーバーヘッドをもたらします。
GraalVM 21.1.0では、Truffle Safepointsの概念が導入されました。
TruffleSafepoint
https://www.graalvm.org/truffle/javadoc/com/oracle/truffle/api/TruffleSafepoint.html
TruffleSafepointは、言語やツールの開発者に、アプリケーションの実行を中断しても安全な時点で実行される、スレッドローカルなアクションを送信する方法を提供します。GraalVM 21.3.0のCPU Samplerは、この新機能を使用するように書き直されており、シャドー・スタックの必要性がなくなり、CPU Samplerを使用する際のCPUとメモリのオーバーヘッドを大幅に削減しています。
Conclusion
CPU Samplerはアプリケーションのパフォーマンス特性を把握するための非常に一般的なツールです。GraalVMは、Truffleフレームワークを使用して構築されたすべての言語向けに言語非依存のCPU Samplerを提供しており、このツールは21.3.0のリリースで大幅に改良されました。
GraalVMの目標の一つは、優れた言語とツールの開発プラットフォームになることです。これを強力に後押しするのが、CPU Samplerのような言語非依存のツールを開発・改良できる機能です。一つのツールが開発されると、そのツールを使っている全ての言語や将来の言語が、個々の言語開発者に負担をかけることなく、すぐに利用できるようになるため、大きな力になります。私たちは、GraalVMをサポートする新しいツールを提供することを楽しみにしています。
CPU Samplerの詳細は以下からどうぞ。
Profiling Command Line Tools
https://www.graalvm.org/tools/profiling/
GraalVM用の独自ツールの実装方法については以下からどうぞ。
Getting Started with Instruments in GraalVM
https://www.graalvm.org/graalvm-as-a-platform/implement-instrument/
GraalVMチームでのインターンシップに興味のある方はインターンシッププログラムをご覧ください。
GraalVM Internship Program
https://www.graalvm.org/community/internship/
Logico Inside 