プログラムのパフォーマンス解析

`gprof` によるコールグラフプロファイルの生成

prof のフラットプロファイルは、パフォーマンス改善のために価値のあるデータを提供しますが、コールグラフプロファイルを利用すれば、さらに詳細な解析を実行できます。コールグラフプロファイルは、どのモジュールがほかのモジュールから呼び出されているか、どのモジュールがほかのモジュールを呼び出しているかを識別する一覧表を表示します。ときには、呼び出しをすべて削除することで、パフォーマンスが改善される場合もあります。

注 -

gprof は関数内の時間を、各 arc が往復する回数に比例して、呼び出し側に割り当てます。しかし、すべての呼び出しで同じ動作をするわけではないため、こうした動作は誤った仮定に陥る可能性もあります。

prof 同様、gprof もプログラムが使用する CPU タイムの統計的プロファイルを生成し、関数に制御が渡される回数をカウントします。gprof はさらに、プログラムのコールグラフにおいて各 arc 上で制御が受け渡される回数もカウントします。arc とは、呼び出す側と呼び出される側の組み合わせを指します。

注 -

Solaris オペレーティング環境のバージョン 2.6 および 7 では、複数の CPU を使用するプログラムに対してCPU 時間のプロファイルは正確ですが、カウントはロックされていなため、関数のカウントの正確さには影響があるかもしれません。

gprof を利用するための手順は以下の 3 段階となっています。

gprof 用のプログラムをコンパイルします。
プログラムを実行して、プロファイルデータファイルを作成します。
gprof を使ってデータを要約したレポートを生成します。

コールグラフプロファイリング用のプログラムをコンパイルするには、C コンパイラに対しては -xpg オプションを、Fortran コンパイラに対しては -pg オプションを使用してください。以下に例を示します。

% cc -xpg -o index.assist index.assist.c

この結果 index.assist プログラムが実行可能になりました。gprof 用にコンパイルされたプログラムを実行するたびに、コールグラフプロファイルデータが gmon.out という名前のファイルに送られます。そのプログラムを実行するたびに、新しい gmon.out が作成されます。

プロファイルの結果レポートを生成するには、gprof コマンドを使用します。gprof の出力はかなり大量になる可能性があります。そのため、結果をファイルにリダイレクトすると、レポートはかなり読みやすくなるでしょう。gprof の出力を /tmp/g.output というファイルにリダイレクトするには、以下の一連のコマンドを使用してください。

% index.assist 
% ls gmon.out 
gmon.out
% gprof index.assist > /tmp/g.output

gprof の出力は以下の 2 つの主要項目から構成されます。

プロファイリングの実行結果のフラグメントを示すフルコールグラフプロファイル。

prof コマンドのプロファイル結果に類似した、「フラット」プロファイル。

gprof の出力には、要約の各部分がどのような意味を持っているかの説明も含まれます。gprof はさらに標本収集の細分性を示します。

granularity: each sample hit covers 4 byte(s) for 0.07% of 14.74 seconds

ここでは、4 byte(s) とは 1 命令の解像度を意味しています。つまり、各標本が全実行時間の 0.07 パーセントであり、CPU 時間が 10 ミリ秒であることを意味します。

以下に、コールグラフプロファイルの一部を示します。

index	%time	self	descendents	called/total parents called+self called/total children	name	index
-----------------------------------------------
		0.00	14.47	1/1	start	[1]
[2]	98.2	0.00	14.47	1	_main	[2]
		0.59	5.70	760/760	_insert_index_entry	[3]
		0.02	3.16	1/1	_print_index	[6]
		0.20	1.91	761/761	_get_index_terms	[11]
		0.94	0.06	762/762	_fgets	[13]
		0.06	0.62	761/761	_get_page_number	[18]
		0.10	0.46	761/761	_get_page_type	[22]
		0.09	0.23	761/761	_skip_start	[24]
		0.04	0.23	761/761	_get_index_type	[26]
		0.07	0.00	761/820	_insert_page_entry	[34]
-----------------------------------------------
				10392	_insert_index_entry	[3]
		0.59	5.70	760/760	_main	[2]
[3]	42.6	0.59	5.70	760+10392	_insert_index_entry	[3]
		0.53	5.13	11152/11152	_compare_entry	[4]
		0.02	0.01	59/112	_free	[38]
		0.00	0.00	59/820	_insert_page_entry	[34]
				10392	_insert_index_entry	[3]
-----------------------------------------------

この index.assist プログラムの入力ファイルのデータには 761 行が含まれていると想定すると、以下の結論が導き出されます。

fgets は 762 回呼び出されています。fgets の最後の呼び出しは、end-of-file を返します。

insert_index_entry 関数は、main から 760 回呼び出されています。

insert_index_entry 関数が main から 760 回呼び出されていることに加えて、insert_index_entry 関数は自分自身を 10,392 回呼び出しています。つまり、insert_index_entry の再帰性はかなり強いということです。

compare_entry (insert_index_entry から呼び出されている) は 11,152 回呼び出され、これは 760+10,392 回と等しくなります。insert_index_entry が呼び出されるごとに、compare_entry の呼び出しが 1 回存在するということで、これは論理的に矛盾がありません。呼び出し回数に矛盾がある場合は、プログラム論理に何らかの問題があることを疑ってみるべきでしょう。

insert_page_entry は、トータルで 820 回呼び出されています。プログラムがインデックスノードを構築している間に main から 760 回呼び出され、insert_index_entry から 59 回呼び出されています。この頻度は、59 個の同じインデックスエントリが存在し、その結果、それらのページ番号エントリはインデックスノードによってチェーンにリンクされていることを示します。重複するインデックスはその後解放されます。そのため、free() は 59 回呼び出されています。

gprof によるコールグラフプロファイルの生成

`gprof` によるコールグラフプロファイルの生成