Fortran プログラミングガイド

第 8 章

パフォーマンスプロファイリング

この章では、プログラムのパフォーマンスの測定と表示方法を説明します。プログラムがどこでその計算サイクルを最も費やしているか、またどのような効率でシステム資源を使用しているかを知ることが、パフォーマンスのチューニングの前提条件となります。

Sun WorkShop Performance Analyzer

Sun WorkShop Performance Analyzer では、プログラムのパフォーマンスデータを収集し、分析するための高度なツールが提供されています。

• 標本コレクタは、パフォーマンスデータ (呼び出しスタックの統計プロファイル、スレッド同期遅延イベント、ハードウェアカウンタのオーバーフロープロファイル、アドレス空間データ、およびオぺレーティングシステムの要約情報) を収集し、それを実験ファイルに保存します。
• 標本アナライザは、ユーザーが情報を調査できるように、標本コレクタにより記録されたデータを表示します。アナライザはデータを処理し、関数、呼び出し元-呼び出し先、ソース行、分解指示、プログラムのレベルでさまざまなパフォーマンスメトリックを表示します。

  また、標本アナライザを使用すれば、アプリケーションのアドレス空間での関数のロード順序を改善するためのマップファイルを作成することで、アプリケーションのパフォーマンスを細かく調整できます。

ソフトウェア開発者にとってパフォーマンスの調整が主な仕事でないとしても、コレクタとアナライザはソフトウェア開発者向けに設計されています。

使用可能な Collector と Analyzer のコマンド行等価ユーティリティは、次のとおりです。

• dbx には、コレクタと同じ機能を持つデータ収集機能が含まれます。
• コマンド行ユーティリティの er_print(1) は、さまざまなアナライザ表示の ASCII バージョンを印刷しますが、これはコマンド行標本アナライザとして機能します。

詳細については、Sun WorkShop マニュアルの『プログラムのパフォーマンス解析』を参照してください。

time コマンド

プログラムのパフォーマンスと資源の利用状況に関する基本的なデータを収集するには、time(1) コマンドを使用するか、または、csh で set time コマンドを発行するのが最も簡単な方法です。

time コマンドでプログラムを実行すると、プログラム終了時に時間情報行が出力されます。

demo% time myprog The Answer is: 543.01 6.5u 17.1s 1:16 31% 11+21k 354+210io 135pf+0w demo%

各欄の意味は次のとおりです。

ユーザー − システム − 壁時計 − 資源 − メモリー − 入出力 − ページ発生

• ユーザー − ユーザーコード中で約 6.5 秒
• システム − このタスクのシステムコード中で約 17.1 秒
• 壁時計 − 実行完了までに 1 分 16 秒
• 資源 − このプログラムのために使用されたシステム資源は 31 %
• メモリー − 共有プログラムメモリーは 11K バイト、プライベートデータメモリーは 21K バイト
• 入出力 − 読み取りは 354 回、書き込みは 210 回
• ページ発生 − ページフォルトは 135 回、スワップアウトは 0 回

time 出力のマルチプロセッサ解釈

プログラムがマルチプロセッサ環境で並列に実行されたとき、結果の時間の解釈方法は異なります。/bin/time はユーザー時間を異なるスレッドで累積するので、実測時間だけが使用されます。

表示されるユーザー時間にはすべてのプロセッサ上で費やされた時間が含まれるので、かなり大きくなり、パフォーマンスの測定方法としては適していません。より適している測定は実時間、つまり、実測時間です。これは、並列化されたプログラムの正確な時間を得るには、ユーザーのプログラムだけに専念するシステム上で実行しなければならないということも意味します。

gprof プロファイリングコマンド

gprof(1) コマンドは、プログラムの使用時間の詳細な事後解析を副プログラムレベルで提供します。これには、副プログラムが何回呼び出されたか、何がその副プログラムを呼び出し、その副プログラムは何を呼び出したか、ルーチンの実行にどれだけの時間がかかったか、そのルーチンが呼び出したルーチンの実行にどれだけの時間がかかったか、などの解析が含まれます。

gprof プロファイリングを有効にするためには、-pg フラグを付けてプログラムをコンパイルし、リンクします。

demo% f77 -o Myprog -fast -pg Myprog.f ... demo% Myprog demo% gprof Myprog

gprof が意味のある時間情報を得るためには、プログラムが正常終了しなければなりません。

プログラムの終了時、ファイル gmon.out が自動的に作業用のディレクトリに書き込まれます。このファイルには、gprof で解釈するプロファイリングデータが格納されています。

gprof を呼び出すと、標準出力にレポートを生成します。次のページに例を示します。ユーザーのプログラム中にあるルーチンだけでなく、ルーチンが呼び出したライブラリ手続きやルーチンもリストされています。

レポートは、全実行時間のうちプログラムの各手続きがどれだけの時間を消費したのかに関する 2 種類のプロファイル、コールグラフとフラットプロファイルで構成されます。これらは、内容を示すカラムラベルが前に付き、後には索引が続きます。(gprof -b オプションは、内容を示すテキストを削除します。生成される出力の量を制限する他のオプションについては、gprof(1) のマニュアルページを参照してください。)

グラフプロファイルでは、各手続き (副プログラム、手続き) は呼び出し (コール) のツリー表現で表されています。この呼び出しツリー中で手続きを表す行は「関数行」と呼ばれ、先頭のカラムにある角括弧で囲まれた索引番号で識別されます。その上にある行は「親の行」と呼ばれ、その下にある行は「子の行」と呼ばれます。

--------------------------------------------------------------- <親の行> <呼び出し元 1> <親の行> <呼び出し元 2> .... [n] 時間 <関数行> <関数名> <子の行> <呼び出し先 1> <子の行> <呼び出し先 2> .... ---------------------------------------------------------------

コールグラフプロファイルの後には、ルーチンごとの概要を提供するフラットプロファイルが続きます。次に、gprof 出力の例 (編集済み) を示します。

---

注 - ユーザー定義関数の場合、Fortran 名の後に下線が付きます。ライブラリルーチンの場合、先頭に下線が付きます。

---

コールグラフプロファイルの例です。

granularity: each sample hit covers 2 byte(s) for 0.08% of 12.78 seconds called/total parents index %time self descendents called+self name index called/total children 0.00 12.66 1/1 main [1] [3] 99.1 0.00 12.66 1 MAIN_ [3] 0.92 10.99 1000/1000 diffr_ [4] 0.62 0.00 2000/2001 code_ [9] 0.11 0.00 1000/1000 shock_ [11] 0.02 0.00 1000/1000 bndry_ [14] 0.00 0.00 1/1 init_ [24] 0.00 0.00 2/2 output_ [40] 0.00 0.00 1/1 input_ [47] ----------------------------------------------- 0.92 10.99 1000/1000 MAIN_ [3] [4] 93.2 0.92 10.99 1000 diffr_ [4] 1.11 4.52 3000/3000 deriv_ [7] 1.29 2.91 3000/6000 cheb1_ [5] 1.17 0.00 3000/3000 dissip_ [8] ----------------------------------------------- 1.29 2.91 3000/6000 deriv_ [7] 1.29 2.91 3000/6000 diffr_ [4] [5] 65.7 2.58 5.81 6000 cheb1_ [5] 5.81 0.00 6000/6000 fftb_ [6] 0.00 0.00 128/321 cos [21] 0.00 0.00 128/192 __sin [279] ----------------------------------------------- 5.81 0.00 6000/6000 cheb1_ [5] [6] 45.5 5.81 0.00 6000 fftb_ [6] 0.00 0.00 64/321 cos [21] 0.00 0.00 64/192 __sin [279] ----------------------------------------------- ...

フラットプロファイルの概要です。

granularity: each sample hit covers 2 byte(s) for 0.08% of 12.84 seconds % cumulative self self total time seconds seconds calls ms/call ms/call name 45.2 5.81 5.81 6000 0.97 0.97 fftb_ [6] 20.1 8.39 2.5 6000 0.43 1.40 cheb1_ [5] 9.1 9.56 1.17 3000 0.39 0.39 dissip_[8] 8.6 10.67 1.11 3000 0.37 1.88 deriv_ [7] 7.1 11.58 0.92 1000 0.92 11.91 diffr_ [4] 4.8 12.20 0.62 2001 0.31 0.31 code_ [9] 2.5 12.53 0.33 69000 0.00 0.00 __exp [10] 0.9 12.64 0.11 1000 0.11 0.11 shock_[11] ...

• 関数行

上記の例の関数行 [5] は、次のことを表しています。

• cheb1 は 6,000 回呼び出された - 3,000 回は deriv から、3,000 回は diffr から
• cheb1 自体は 2.58 秒を消費した
• cheb1 が呼び出したルーチンは 5.81 秒を消費した
• プログラムの実行時間の 65.7 % は cheb1 であった
• 親の行

[5] より上にある親の行は、cheb1 が 2 つのルーチン deriv と diffr から呼び出されたことを示しています。これらの行上の時間情報は、それぞれのルーチンから cheb1 が呼び出されたとき、cheb1 でどのくらいの時間が消費されたかを示します。

• 子の行

関数行の下にある行は、cheb1 から 3 つのルーチン fftb、cos、および sin が呼び出されたことを示しています。ライブラリの sin 関数も間接的に呼び出されています。

• フラットプロファイル

関数名は右側に現れます。プロファイルは、全実行時間のパーセンテージでソートされます。

オーバーヘッドについての考察

プロファイリングを行う (-pg オプションを付けてコンパイルする) と、プログラムの実行時間はかなり増加します。これは、プログラムのパフォーマンスと副プログラムの呼び出しを計測するのに必要なオーバーヘッドがあるためです。gprof のような プロファイリングツールは、相対的な実行時パーセンテージを計算するとき、おおよそのオーバーヘッド要因を差し引こうとします。UNIX とハードウェアの計時の不正確さのため、表示されるその他の時間は必ずしも正確ではありません。

実行時間が短いプログラムのプロファイリングを行うのは最も困難です。なぜなら、オーバーヘッドが全実行時間のかなりの部分を占めるからです。最良の方法は、プログラムのパフォーマンスの現実的なテストになるような、プロファイリング実行用の入力データを選ぶことです。これが不可能な場合、プログラムの主な計算部分をループで囲み、そのプログラムを N 回実行する方法を考えてみてください。プロファイルの結果を N で割ると、実際のパフォーマンスの概算が得られます。

Fortran ライブラリには、呼び出し側のプロセスが使用した合計時間を返すルーチンが 2 つあります。dtime(3F) と etime(3F) のマニュアルページを参照してください。

また、gprof では誤った結果が返される可能性があります。よく知られている制限は、gprof では複数の呼び出し元から呼び出された関数の中で時間が経過してしまうとそれを区別できないことです。たとえば、FU 関数の処理時間は BAR ルーチンから呼び出されたときの方がそのほかのルーチンから呼び出されたときよりも時間がかかることがありますが、それがわかればプログラムを大幅に編成し直して、パフォーマンスを上げるようにお勧めできます。残念ながら、gprof での結果により、すべての呼び出しにおけるFU関数の処理時間の合計から平均が算出されるので、重要な情報もあいまいになってしまいます。Sun WorkShop Performance Analyzer では、プログラムの厳密なパフォーマンス解析を行いたい場合、またそのような解析を使用しなければならない場合のために、より詳細で有用な情報を提供しています。

tcov プロファイリングコマンド

tcov(1) コマンドは、-a、-xa、-xprofile=tcov オプションを付けてコンパイルしたプログラムとともに使用すると、どの文がどれくらい実行されたかを示す、ソースコードの文ごとのプロファイルを生成します。また、プログラムの基本ブロック構造に関する情報の要約も提供します。

tcov のカバレージの解析には実装により 2 種類があります。オリジナルの tcov は、-a または -xa コンパイラオプションによって呼び出されます。拡張された文レベルのカバレージは、-xprofile=tcov コンパイラオプションと -x tcov オプションによって呼び出されます。どちらの場合でも、出力はソースファイルのコピーであり、各文のマージンに実行回数が注釈されています。Fortran ユーザーに関しては、これらの 2 つの tcov のバージョンは本質的には同じですが (拡張のほとんどは C++ プログラムに適用される)、新しいスタイルではパフォーマンスが少しだけ向上しています。

---

注 - tcov により生成されたコード適用範囲レポートは、コンパイラがルーチン呼び出しをインライン化した場合は信頼性が低くなります。コンパイラは、最適化レベルが -0.3 以上で -inline オプションが指定されている場合は呼び出しをインライン化します。それにより、コンパイラはルーチンへの呼び出しを呼び出し先ルーチンの実コードに置き換えます。このとき、呼び出しがないので、これらのインライン化されたルーチンへの参照は tcov により報告されません。そのため正しい適用範囲レポートを取得するには、コンパイラのインライン化機能を有効にしてはなりません。

---

古いスタイルの tcov カバレージ解析

プログラムを -a (または -xa) オプションを付けてコンパイルします。これによって、コンパイル中、ソースファイル (.f ファイル) ごとに $TCOVDIR/file.d というファイルが作成されます。コンパイル時に環境変数 $TCOVDIR が設定されていない場合、.d ファイルは現在のディレクトリに格納されます。

プログラムを実行します。実効は必ず正常終了しなければなりません。これによって、更新された情報が .d ファイルに生成されます。個々のソースファイルにマージされたカバレージ解析を表示するには、ソースファイル上で tcov を実行します。注釈付きソースファイルの名前は、各ソースファイルに対して $TCOVDIR/file.tcov となります。

tcov によって生成された出力は、それぞれの文が実際に何回実行されたかを示します。実行されなかった文の左側には、####-> というマークが付きます。

次に簡単な例を示します。

demo% f77 -a -o onetwo -silent one.f two.f demo% onetwo ... プログラムからの出力が表示される demo% tcov one.f two.f demo% cat one.tcov two.tcov program one 1 -> do i=1,10 10 -> call two(i) end do 1 -> end Top 10 Blocks Line Count 3 10 2 1 5 1 3 Basic blocks in this file 3 Basic blocks executed 100.00 Percent of the file executed 12 Total basic block executions 4.00 Average executions per basic block subroutine two(i) 10 -> print*, "two called", i return end Top 10 Blocks Line Count 2 10 1 Basic blocks in this file 1 Basic blocks executed 100.00 Percent of the file executed 10 Total basic block executions 10.00 Average executions per basic block demo%

新しいスタイルの拡張 tcov 解析

新しいスタイルの tcov を使用するには、-xprofile=tcov を付けてコンパイルします。プログラムを実行するとき、カバレージデータは program.profile/tcovd に格納されます。program は実行可能ファイルの名前です。実行可能ファイルが a.out の場合、a.out.profile/tcovd が作成されます。

tcov -x dirname source_files を実行して、ソースファイルごとにマージされたカバレージ解析を作成します。レポートは、現在のディレクトリにある file.tcov に書き込まれます。

簡単な例を実行します。

demo% f77 -o onetwo -silent -xprofile=tcov one.f two.f demo% onetwo ... プログラムからの出力が表示される demo% tcov -x onetwo.profile one.f two.f demo% cat one.f.tcov two.f.tcov program one 1 -> do i=1,10 10 -> call two(i) end do 1 -> end .....etc demo%

環境変数 $SUN_PROFDATA と $SUN_PROFDATA_DIR を使用すると、中間データ収集ファイルが格納される場所を指定できます。中間データ収集ファイルは *.d と tcovd ファイルで、それぞれ古いスタイルの tcov と新しいスタイルの tcov によって作成されます。

それぞれ、この後の実行のたびに tcovd ファイルに、さらにデータが追加されます。各オブジェクトファイルのデータは、ソースファイルが再コンパイルされた後にプログラムがはじめて実行されるときにクリアーされます。プログラム全体のデータは、tcovd ファイルを削除したときにクリアーされます。

これらの環境変数を使用して、異なる実行から収集されたデータを分けることができます。これらの環境変数を設定すると、実行プログラムは実行データを $SUN_PROFDATA_DIR/$SUN_PROFDATA/ 中のファイルに書き込みます。

同様に、tcov が読み出すディレクトリは、tcov -x $SUN_PROFDATA で指定されます。$SUN_PROFDATA_DIR が設定された場合、tcov はそれを前に付けて、作業中のディレクトリではなく、$SUN_PROFDATA_DIR/$SUN_PROFDATA/ 中でファイルを探します。

詳細は、tcov(1) のマニュアルページを参照してください。

f77: 入出力のプロファイリング

ユーザープログラムによるデータ転送がどのくらい行われたかに関するレポートを作成できます。レポートは、各 Fortran 装置に対して、ファイル名、入出力文の数、バイト数、これらに関する統計情報を示します。

入出力プロファイリングレポートを得るには、測定したいプログラムの部分の前後に、ライブラリルーチン start_iostats と end_iostats への呼び出しを挿入します (プログラムが CALL EXIT 文ではなく END 文または STOP 文で終了する場合、end_iostats への呼び出しが必要です)。

---

注意 - プロファイルの対象となる入出力文は、READ、WRITE、PRINT、OPEN、CLOSE、INQUIRE、BACKSPACE、ENDFILE、REWIND です。実行時のシステムは、ユーザーのプログラムの最初の実行可能文より前に stdin、stdout、stderr を開きます。このため、これらの装置は、start_iostats への呼び出し後に明示的に開き直さなくてはなりません。

---

例 : stdin、stdout、stderr についてプロファイルを実行します。

EXTERNAL start_iostats ... CALL start_iostats OPEN(5) OPEN(6) OPEN(0)

プログラムの一部分だけを測定したい場合は、end_iostats を呼び出し、そこでプロセスを停止します。ユーザーのプログラムが CALL EXIT 文ではなく END 文または STOP 文で終了する場合も、end_iostats への呼び出しが必要になります。

プログラムは -pg オプションを付けてコンパイルしなければなりません。プログラムが終了した後、入出力プロファイルレポートがファイル name.io_stats に生成されます。 name は実行可能ファイルの名前です。

次に例を示します。

demo% f77 -o myprog -pg -silent myprog.f demo% myprog ... プログラムからの出力が表示される demo% cat myprog.io_stats INPUT REPORT 1. unit 2. file name 3. input data 4. map cnt total avg std dev (cnt) ------------------------------------------------------------------------ 0 stderr 0 0 0 0 No 0 0 0 0 5 stdin 2 8 4 0 No 1 8 8 0 6 stdout 0 0 0 0 No 0 0 0 0 19 fort.19 8 48 6 4.276 No 4 48 12 0 20 fort.20 8 48 6 4.276 No 4 48 12 0 21 fort.21 8 48 6 4.276 No 4 48 12 0 22 fort.22 8 48 6 4.276 No 4 48 12 0 OUTPUT REPORT 1. unit 5. output data 6. blk size 7. fmt 8. direct cnt total avg std dev (rec len) ----------------------------------------------------------------------------- 0 4 40 10 0 -1 Yes seq 1 40 40 0 5 0 0 0 0 -1 Yes seq 0 0 0 0 6 26 248 9.538 1.63 -1 Yes seq 6 248 41.33 3.266 19 8 48 6 4.276 500548 Yes seq 4 48 12 0 20 8 48 6 4.276 503116 No seq 4 48 12 0 21 8 48 6 4.276 503116 Yes dir 4 48 12 0 ( 12) 22 8 48 6 4.276 503116 No dir 4 48 12 0 ( 12) ...

レポート中の行のペアはそれぞれ、入出力装置に関する情報を示します。入力動作を示すセクションと出力動作を示すセクションがあります。ペアの最初の行は、その装置が閉じられるまでに転送されたデータ要素の数に関する統計を示します。統計の 2 番目の列は、処理された入出力文の数に基づいて作成されます。

例では、6 つの呼び出しが合計 26 のデータ要素を標準出力に書き込んでいます。合計で 248 バイトが転送されています。また、入出力文ごとに転送されたバイトの平均と標準偏差がそれぞれ 9.538 と 1.63 であり、入出力文呼び出しごとのバイトの平均と標準偏差が 42.33 と 3.266 であることを示しています。

入力レポートには、装置がメモリーにマップされたかどうかを示すカラムもあります。マップされていれば、mmap() 呼び出しの数がペアの 2 番目の列の括弧の中に記録されます。

出力レポートは、ブロックサイズ、書式、探査の種類を示します。直接探査用に開かれたファイルは、ペアの 2 番目の列の括弧の中にその定義された記録長を示します。

---

注 - 環境変数 LD_LIBRARY_PATH を設定してコンパイルすると、入出力プロファイリングが無効になります。入出力プロファイリングは、標準の位置にあるそのプロファイリング用の入出力ライブラリに依存するからです。

---