レベル: 初級 Martyn Honeyford (ibmmartyn@gmail.com), Software Engineer, IBM
2006年 4月 03日 アプリケーション性能の向上が無駄な作業に終わることはまずありませんが、プログラム実行時にどの部分で最も時間を費やしているのかは、常に明確になっているわけではありません。gprofを使用して、ユーザー空間およびLinux®
™ のシステム呼び出しの双方において、性能のボトルネックになっている部分を突き止める方法を説明します。
はじめに
ソフトウェアの性能ニーズは様々ですが、多くのアプリケーションにおいて速度の要件が非常に厳しいことは、さほど驚くことではありません。ビデオ・プレイヤーなどがいい例です。要求速度の75%でしかビデオを再生できないビデオ・プレイヤーは、あまり役に立ちません。
ビデオ・エンコードのようなアプリケーションは非常に長い処理を伴うため、あるジョブを開始し、そのまま実行させながら他の作業を行うような「バッチ」スタイルで稼動するのが最適です。この種のアプリケーションには厳しい性能上の制限はありませんが、速度が速ければ一定時間内により多くのビデオをエンコードでき、同じ時間内でより高い品質のエンコードができるなどの利点が生じます。
最も単純なアプリケーションを除いたほとんどのアプリケーションの場合、性能が向上するほどより便利になり、人気も出てきます。こうした理由から、多くのアプリケーション開発者にとって性能への配慮は最重要事項になっています（またはなっているべきです）。
しかしながら、開発者はプログラムがどのように作動するのかを広い視野から十分に調査することなくソフトウェアの細かい部分だけを最適化してしまうため、アプリケーションの速度向上のために行われた作業の大半が無駄になってしまいます。たとえば、ある機能の処理速度を2倍にするため、大量の時間を費やすとします。それ自体は何の問題もありませんが、その機能はめったに呼び出されないと機能だとしたら(ファイルのオープン時に呼び出されるような場合)、実行時間を200msから100msに短縮したところで、ソフトウェアの全体的な実行時間に大きな影響はありません。
ソフトウェアにおいては、より頻繁に呼び出される部分を最適化するのが効率的です。たとえば、アプリケーションが全体の処理時間の50% をストリング処理機能に費やしている場合、この機能を10% 最適化できれば、アプリケーション全体の実行時間を5% 改善することができます。
そのため、アプリケーションの最適化を効率的に行う場合、アプリケーションのどの部分で、あるいは実際に入力されるデータのどの部分で処理に時間がかかっているのかを正確に知ることのできる情報が不可欠になります。このための作業は、コード・プロファイルと呼ばれます。この記事では、オープン・ソース開発ツールに関して比較的馴染みの薄い読者のために、GNUコンパイラー・ツール・チェーンによって提供されるプロファイル・ツールを紹介します。ここでは、このツールを便宜上GNUプロファイラー(gprof)と呼びます。
gprofを使用する
gprofの使用方法を説明する前に、開発サイクルのどの部分でプロファイルが行われるべきかを理解することが重要になります。一般的に、コードは以下の3つの目標に基づいて記述する必要があります。以下の項目は重要度順になっています。
- ソフトウェアが正確に作動するようにします。このことは、常に開発の中心に置かなければなりません。どんなに処理速度の速いソフトウェアを作成したところで、本来の機能が果たせなければ意味がありません。いうまでもなく、「正確に動作する」という場合の正確さというのはかなりあいまいな部分です。99% のファイルで作動する、またはビデオを再生する際に視覚上の問題が時々発生するビデオ・プレイヤーでも、一応使用には耐えますが、一般的には処理速度の速さよりも正確さの方が重要です。
-
保守が可能なソフトウェアにします。これは、実際には上の目標を補完するものです。一般的に、ソフトウェアが保守可能な形で記述されていない場合、最初の頃は正常に作動したとしても、遅かれ早かれ、作成者(または他の誰か)がバグを修正したり新たな機能を追加する際に、保守が可能な形に変更することになります。
- ソフトウェアの処理速度を速くします。ここでプロファイルが登場します。ソフトウェアが正しく作動したら、次にプロファイルを開始して処理速度を上げます。
正常に作動しているアプリケーションがあると仮定し、アプリケーションの実行中にgprofを使用して、どの部分で処理に時間がかかっているのかを正確に測定する方法について見てみましょう。この作業により、どの部分を最適化すれば最も効果的なのかがわかります。
gprofはC、C++、PascalおよびFortran 77のアプリケーションをプロファイルすることができます。以下の例ではC言語を使用しています。
リスト1.時間浪費型アプリケーションのサンプル
#include <stdio.h>
int a(void) {
int i=0,g=0;
while(i++<100000)
{
g+=i;
}
return g;
}
int b(void) {
int i=0,g=0;
while(i++<400000)
{
g+=i;
}
return g;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s <No of Iterations>\n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
|
コードを見てわかるように、このごく単純なアプリケーションにはaとbという2つの機能があり、これらの機能はCPUサイクルを浪費する処理量の多いループ内に置かれています。メインの機能は、これらの機能を呼び出すループ内にあります。第2の機能であるbはaの4倍ループするため、一度コードをプロファイルすれば、aに約20%の時間がかかり、bに約80%の時間がかかると予想できます。プロファイル機能を有効にして、この予想が正しいか検証してみましょう。
プロファイル機能は、-pgをgccコンパイル・フラグに追加するだけで有効にすることができます。以下のようにコンパイルしてください。
gcc example1.c -pg -o example1 -O2 -lc
アプリケーションが構築できたら、あとは通常通りに実行するだけです。
./example1 50000
この作業が完了すると、現行ディレクトリーにgmon.outという名のファイルが作成されているはずです。
出力を使用する
最初に、「フラット・プロファイル」を見てください。これは、実行可能ファイルとgmon.outファイルを以下のように送信してgprofコマンドを実行すると作成されます。
gprof example1 gmon.out -p
これにより、以下の内容が出力されます。
リスト2.フラット・プロファイルの結果
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
80.24 63.85 63.85 50000 1.28 1.28 b
20.26 79.97 16.12 50000 0.32 0.32 a
|
この出力から、予想通りbにはaのほぼ4倍の時間がかかっていることがわかります。実際の値は丸め誤差によって非常に不正確になる傾向があるため、あまり役には立ちません。
このリストを注意深く見ると、呼び出された機能の多く(printfなど)が出力されていないことに気が付くでしょう。これは、(この場合には)-pgでコンパイルされていないCランタイム・ライブラリー(libc.so)内にこうした機能が格納されているためです。そのため、このライブラリー内に格納されている機能については、一切プロファイルが収集されませんでした。このことについては後で説明します。
次に、以下のコマンドで作成される「コール・グラフ」を見てみましょう。
gprof example1 gmon.out -q
これにより、以下の内容が出力されます。
リスト3.コール・グラフ
Call graph (explanation follows)
granularity: each sample hit covers 2 byte(s) for 0.01% of 79.97 seconds
index % time self children called name
<spontaneous>
[1] 100.0 0.00 79.97 main [1]
63.85 0.00 50000/50000 b [2]
16.12 0.00 50000/50000 a [3]
-----------------------------------------------
63.85 0.00 50000/50000 main [1]
[2] 79.8 63.85 0.00 50000 b [2]
-----------------------------------------------
16.12 0.00 50000/50000 main [1]
[3] 20.2 16.12 0.00 50000 a [3]
-----------------------------------------------
|
最後に、各機能が何回呼び出されたかという注釈と共に、アプリケーションにソース・コードをプリント・アウトする「注釈付きソース」のリストを作成することができます。
この機能を使用するには、ソースが実行可能になるように、デバッグ機能を有効にしてからソースをコンパイルします。
gcc example1.c -g -pg -o example1 -O2 -lc
前述と同様にアプリケーションを再実行します。
./example1 50000
現在のgprofコマンドは、以下のようになります。
gprof example1 gmon.out -A
これにより、以下の内容が出力されます。
リスト4.注釈付きソース
*** File /home/martynh/profarticle/example1.c:
#include <stdio.h>
50000 -> int a(void) {
int i=0,g=0;
while(i++<100000)
{
g+=i;
}
return g;
}
50000 -> int b(void) {
int i=0,g=0;
while(i++<400000)
{
g+=i;
}
return g;
}
int main(int argc, char** argv)
##### -> {
int iterations;
if(argc != 2)
{
printf("Usage %s <No of Iterations>\n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
Top 10 Lines:
Line Count
3 50000
11 50000
Execution Summary:
3 Executable lines in this file
3 Lines executed
100.00 Percent of the file executed
100000 Total number of line executions
33333.33 Average executions per line
|
共有ライブラリー・サポート
上で説明したように、コンパイラーによってプロファイル・サポート機能が追加されるため、Cライブラリー(libc.a)などの任意の共有ライブラリーからプロファイル情報を取得したい場合は、そうしたライブラリーにも?pgを付けてコンパイルする必要があります。都合のいいことに、多くの配布版は、すでにプロファイル・サポート(libc_p.a)がコンパイルされたCライブラリーのバージョンと共に出荷されています。
私が使用している配布版のgentooでは、USEフラグに「profile」を追加してglibcを再出現させる必要があります。これが終われば、/usr/lib/libc_p.aが作成されたことが確認できるはずです。標準としてlibc_pと共に出荷されていない配布版については、別々にインストールすることは可能かを確認する必要があります。あるいは、glibcソースをダウンロードして自分で構築する必要があるかもしれません。
libc_p.aファイルが作成されたら、以下のように例を単純に再構築することができます。
gcc example1.c -g -pg -o example1 -O2 -lc_p
次に、前述のようにアプリケーションを再実行してフラット・プロファイルとコール・グラフを取得すれば、printfをはじめとする多くのCランタイム機能を確認できるはずです(このテスト・プログラムでは、いずれの機能もあまり重要ではありません)。
ユーザー時間対カーネル時間
これでgprofの使用方法がわかりました。アプリケーションのプロファイルは大変簡単で効果的です。アプリケーションの分析はもちろんのこと、性能のボトルネックを取り除くことも可能です。
しかし、ここまで見てきたところで、gprof'の最大の制約に気が付いたかもしれません。アプリケーションの実行中は、gprof'はユーザー時間しかプロファイルしません。通常の場合、アプリケーションはユーザー・コードに一定の時間を費やしながら、カーネル・システム・コールの場合のように「システム・コード」にも一定の時間を費やします。
以下のように、リスト1を少しだけ修正すれば、問題点が明らかになります。
リスト5.リスト1にシステム・コードを追加
#include <stdio.h>
int a(void) {
sleep(1);
return 0;
}
int b(void) {
sleep(4);
return 0;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s <No of Iterations>\n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
|
これを見てわかるように、aおよびbを処理量の多いループ内に置くのではなく、Cランタイム・スリープ機能を呼び出してaが1秒間、bが4秒間処理を中断するようにコードを修正しました。
前の例と同じように、このアプリケーションを以下のようにコンパイルします。
gcc example2.c -g -pg -o example2 -O2 -lc_p
次に、以下のように30回ループするように指定して実行します。
./example2 30
作成されたフラット・プロファイルは、以下のようになります。
リスト6.システム・コールを示すフラット・プロファイル
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 120 0.00 0.00 sigprocmask
0.00 0.00 0.00 61 0.00 0.00 __libc_sigaction
0.00 0.00 0.00 61 0.00 0.00 sigaction
0.00 0.00 0.00 60 0.00 0.00 nanosleep
0.00 0.00 0.00 60 0.00 0.00 sleep
0.00 0.00 0.00 30 0.00 0.00 a
0.00 0.00 0.00 30 0.00 0.00 b
0.00 0.00 0.00 21 0.00 0.00 _IO_file_overflow
0.00 0.00 0.00 3 0.00 0.00 _IO_new_file_xsputn
0.00 0.00 0.00 2 0.00 0.00 _IO_new_do_write
0.00 0.00 0.00 2 0.00 0.00 __find_specmb
0.00 0.00 0.00 2 0.00 0.00 __guard_setup
0.00 0.00 0.00 1 0.00 0.00 _IO_default_xsputn
0.00 0.00 0.00 1 0.00 0.00 _IO_doallocbuf
0.00 0.00 0.00 1 0.00 0.00 _IO_file_doallocate
0.00 0.00 0.00 1 0.00 0.00 _IO_file_stat
0.00 0.00 0.00 1 0.00 0.00 _IO_file_write
0.00 0.00 0.00 1 0.00 0.00 _IO_setb
0.00 0.00 0.00 1 0.00 0.00 ____strtol_l_internal
0.00 0.00 0.00 1 0.00 0.00 ___fxstat64
0.00 0.00 0.00 1 0.00 0.00 __cxa_atexit
0.00 0.00 0.00 1 0.00 0.00 __errno_location
0.00 0.00 0.00 1 0.00 0.00 __new_exitfn
0.00 0.00 0.00 1 0.00 0.00 __strtol_internal
0.00 0.00 0.00 1 0.00 0.00 _itoa_word
0.00 0.00 0.00 1 0.00 0.00 _mcleanup
0.00 0.00 0.00 1 0.00 0.00 atexit
0.00 0.00 0.00 1 0.00 0.00 atoi
0.00 0.00 0.00 1 0.00 0.00 exit
0.00 0.00 0.00 1 0.00 0.00 flockfile
0.00 0.00 0.00 1 0.00 0.00 funlockfile
0.00 0.00 0.00 1 0.00 0.00 main
0.00 0.00 0.00 1 0.00 0.00 mmap
0.00 0.00 0.00 1 0.00 0.00 moncontrol
0.00 0.00 0.00 1 0.00 0.00 new_do_write
0.00 0.00 0.00 1 0.00 0.00 printf
0.00 0.00 0.00 1 0.00 0.00 setitimer
0.00 0.00 0.00 1 0.00 0.00 vfprintf
0.00 0.00 0.00 1 0.00 0.00 write
|
この出力を分析すると、プロファイラーが各機能の呼び出し回数を正確に登録しているにもかかわらず、これらの機能(実際にはすべての機能)の登録時間が0.00であることがわかります。これは、スリープ機能がアプリケーションを中断するようカーネル空間に対して呼び出しを行い、その結果実際に処理が中断され、カーネルによって再びこの処理が起動されるのを待機しているためです。ユーザー空間における処理の総時間数は、カーネル空間での待機時間と比較するとごく僅かであるため、値はゼロに丸められます。これは、プログラムの実行時に合わせた固定周期で測定が行なわれるようにプログラムを設定することにより、gprofが機能するためです。したがって、プログラムが稼動していない場合には、一切測定は行われません。
これは実にありがた迷惑な話です。ほとんどの時間をカーネル空間で費やすアプリケーションや、オペレーティング・システムのI/Oサブシステムへの過負荷などの外部要因によって実行速度が遅くなっているアプリケーションについては、最適化の実行が困難になるという欠点があります。これは逆の見方をすれば、プロファイル処理が、システム上のどんな状態(別のユーザーがCPU時間を大量に使用している場合など)にも影響を受けないという利点になります。
一般的に、アプリケーションの最適化を行う場合にgprofの有用性を確認するのに適したベンチマークは、アプリケーションをtimeコマンドの下で実行することです。このコマンドは、アプリケーションが処理を完了するまでにかかる時間を記録し、ユーザー空間とカーネル空間でそれぞれに費やした時間も測定します。
リスト2の例を見てみます。
time ./example2 30
以下が出力されます。
リスト7.timeコマンドの出力
No of iterations = 30
real 2m30.295s
user 0m0.000s
sys 0m0.004s
|
ユーザー空間において、コード処理にはほとんど時間がかからなかったことがわかります。ここでは、gprofがあまり役に立たないことが分かります。
まとめ
これまでに説明した制約にもかかわらず、gprofは、コードを最適化する上で非常に便利なツールとなります。コードがユーザー空間内でCPUの制約を受ける場合に、特に便利です。通常の場合は、アプリケーションを最初にtimeの下で実行して、gprofによって有効な情報が作成されるかを判断するのがいいでしょう。
gprofがプロファイルのニーズに適さない場合、OProfileやSysprofなど(これらのツールの詳細については「参考文献」を参照してください)、gprofのいくつかの制約を解決することができる手段が数多くあります。
その一方で、gccがインストールされていると仮定すると、gprofを他の手段と比較した場合の最大の利点の1つに、使用しているどのLinuxマシンにおいてもgccがすでにインストールされている可能性が高いという利点があります。
参考文献
学ぶ
製品や技術を入手する
-
無料の2枚組DVDセットのSEK for Linuxを注文することができます。DB2®、Lotus®、Rational®、Tivoli®、WebSphere® など、Linux用の最新IBMソフトウェア試用版が含まれています。
-
IBMの体験版ソフトウェアは、developerWorksのサイトから直接ダウンロードできます。このソフトウェアを使用して、次のLinuxプロジェクトを開発してください。
議論する
著者について  | | | Martyn Honeyfordは1996年にNottingham大学をコンピュータ・サイエンスの学位を取得して卒業しました。それ以来、イギリスHursleyにあるIBM UK Labsでソフトウェア技術者として勤務しています。現在はWebSphere MQ Everyplace開発チームの開発メンバーとして活躍しています。仕事がないときにはエレキ・ギターを弾いているか（上手くありません）、普通の人からは不健康に思えるほどテレビ・ゲームにのめり込んでいます。 |
記事の評価
| 
