13.7 プロファイラの例
以下に、プロファイラ セッションの簡単な例を示します。プロファイラ関数の詳細なドキュメントについては、プロファイリングを参照してください。次のコードを考えてみましょう。
global N A;
N = 300; A = rand (N, N);
function xt = timesteps (steps, x0, expM) global N;
if (steps == 0) xt = NA (N, 0); else xt = NA (N, steps); x1 = expM * x0; xt(:, 1) = x1; xt(:, 2 : end) = timesteps (steps - 1, x1, expM); endif endfunction
function foo () global N A;
initial = @(x) sin (x); x0 = (initial (linspace (0, 2 * pi, N)))';
expA = expm (A); xt = timesteps (100, x0, expA); endfunction
function fib = bar (N) if (N <= 2) fib = 1; else fib = bar (N - 1) + bar (N - 2); endif endfunction
2 つの主な関数を実行すると、次のようになります。
tic; foo; toc; ⇒ Elapsed time is 2.37338 seconds.
tic; bar (20); toc; ⇒ Elapsed time is 2.04952 seconds.
しかし、これだけでは、この時間がどこで費やされているかについてはあまり情報が得られません。たとえば、 への単一の呼び出しの方expmがコストが高いのか、それとも再帰的なタイムステップ自体の方がコストが高いのかなどです。より詳細な情報を得るには、プロファイラーを使用できます。
profile on; foo; profile off;
data = profile ("info");
profshow (data, 10);
This prints a table like:
# Function Attr Time (s) Calls
7 expm 1.034 1 3 binary * 0.823 117 41 binary \ 0.188 1 38 binary ^ 0.126 2 43 timesteps R 0.111 101 44 NA 0.029 101 39 binary + 0.024 8 34 norm 0.011 1 40 binary - 0.004 101 33 balance 0.003 1
エントリは実行された個々の関数（最も重要な10個のみ）と、それぞれの情報です。「バイナリ *' は演算子を表し、他のエントリは通常の関数です。これらには、組み込みの のような関数 expmと独自のルーチン (たとえば) の両方が含まれます。このプロファイルから、 は 1 回しか呼び出されないにもかかわらず、処理時間の大部分をtimesteps消費することがすぐにわかりますexpm。2 番目に時間のかかる演算は、ルーチン の行列ベクトル積です
timesteps. 6
ただし、タイミングはプロファイルから得られる唯一の情報ではありません。属性列には、がtimesteps自分自身を再帰的に呼び出すことが示されています。これはこの例ではそれほど目立たないかもしれませんが (いずれにしても明らかなので)、より複雑な設定では役立つ可能性があります。なぜ「バイナリ \' という出力があれば、これも簡単に解明できます。 は、フィールド を含むdata構造体配列 (構造体配列FunctionTable) であることに注意してください。ここには、表示されているプロファイルの生データが格納されます。表の最初の列の番号は、表示されている関数が見つかるインデックスを示します。検索すると、data.FunctionTable(41)次のようになります。
scalar structure containing the fields:
FunctionName = binary \ TotalTime = 0.18765 NumCalls = 1 IsRecursive = 0 Parents = 7 Children = [](1x0)
ここで、表の情報を再度確認しますが、フィールド と が追加されていますParents。Childrenこれらは両方とも配列であり、問題の関数を直接呼び出した関数 (expmこの場合はエントリ 7、 ) または問題の関数によって呼び出された関数 (関数なし) のインデックスが含まれています。したがって、バックスラッシュ演算子は によって内部的に使用されていますexpm。
それでは、 を見てみましょうbar。このために、新しいプロファイリング セッションを開始します (profile onは次の処理を行います。プロファイラーが再起動される前に古いデータが削除されます)。
profile on; bar (20); profile off;
profshow (profile ("info"));
これにより、次のようになります。
# Function Attr Time (s) Calls
1 bar R 2.091 13529 2 binary <= 0.062 13529 3 binary - 0.042 13528 4 binary + 0.023 6764 5 profile 0.000 1 8 false 0.000 1 6 nargin 0.000 1 7 binary != 0.000 1 9 __profiler_enable__ 0.000 1
当然のことながら、barも再帰的です。 フィボナッチ数を次善の方法で再帰的に計算する過程で 13,529 回呼び出され、ほとんどの時間がbarそれ自体に費やされました。
foo 最後に、 との両方の実行を一緒にプロファイリングするとしますbar。 の実行時データがすでに収集されているためbar、既存のデータを消去せずにプロファイラーを再起動し、 に関する不足している統計情報を収集できますfoo。これは次のように行います。
profile resume; foo; profile off;
profshow (profile ("info"), 10);
下の表からわかるように、現在、両方のプロファイルが混在しています。
# Function Attr Time (s) Calls
1 bar R 2.091 13529 16 expm 1.122 1 12 binary * 0.798 117 46 binary \ 0.185 1 45 binary ^ 0.124 2 48 timesteps R 0.115 101 2 binary <= 0.062 13529 3 binary - 0.045 13629 4 binary + 0.041 6772 49 NA 0.036 101
脚注
(6)
バイナリ乗算演算子であることだけが分かっていますが、幸いにもこの演算子はコード内の 1 か所にしか出現しないため、どの箇所に多くの時間がかかっているかが分かります。複数の箇所に出現する場合は、階層プロファイルを使用して、時間のかかる箇所を正確に特定する必要がありますが、この例ではその点については触れていません。