プロファイリング

Profileモジュールには、開発者がコードのパフォーマンスを向上させるのに役立つツールが用意されています。使用すると、実行中のコードを測定し、各行の演算にどれくらいの時間が費やされているかを理解するのに役立つ出力を生成します。最も一般的な使用法は、最適化のターゲットとして「ボトルネック」を特定することです。

Profileには、「サンプリング」すなわち、統計的プロファイラーとして知られているものを実装されています。これは、任意のタスクの実行中に定期的にバックトレースを取ることによって動作します。各バックトレースは、現在実行中の関数と行番号、そして、この行の実行につながる関数呼び出しの完全な連鎖を補足します。そのため、(バックトレースで得られる状態は)現在の実行状態の "スナップショット" になります。

実行時間の多くが特定のコード行の実行に費やされている場合、この行はすべてのバックトレースのセットに頻繁に現れます。言い換えれば、特定の行の「コスト」、つまり、この行を含む関数の一連の呼び出しのコストは、すべてのバックトレースのセットに表示される頻度に比例します。

サンプリングプロファイラは、1行1行の実行に対する完全なカバレッジを提供しません。バックトレースが一定時間間隔で発生するからです(既定では、Unix システムで 1 ミリ秒、Windows では 10 ミリ秒ですが、実際のスケジューリングはオペレーティングシステムの負荷の影響を受けます)。さらに、後で説明するように、サンプルは全実行ポイントに対してサンプル数のまばらな部分集合として収集されるため、サンプリングプロファイラによって収集されたデータは統計的ノイズの影響を受けます。

これらの制限にもかかわらず、サンプリングプロファイラには大きな強みがあります:

演算時間測定を行うためにコードを変更する必要はありません。
Juliaのコアコードの中まで、さらには(オプションで)CおよびFortranライブラリの中もプロファイルすることができます。
"まれに" 実行する分には、パフォーマンスのオーバーヘッドはほとんどありません。プロファイリング中は、コードはほぼネイティブの速度で実行できます。

このような理由から、代替案を検討する前に、組み込みのサンプリングプロファイラを使用することをお勧めします。

基本的な使い方

簡単なテストケースを試してみましょう:

julia> function myfunc()
           A = rand(200, 200, 400)
           maximum(A)
       end

プロファイルするコードを少なくとも 1 回実行しておくのはよいアイディアです (Julia の JIT コンパイラをプロファイリングする場合を除く):

julia> myfunc() # run once to force compilation

これで、この関数をプロファイルする準備ができました:

julia> using Profile

julia> @profile myfunc()

プロファイリング結果を確認するには、グラフィカルブラウザを使用できますが、ここでは標準ライブラリに付属のテキストベースの表示を使用します:

julia> Profile.print()
80 ./event.jl:73; (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
 80 ./REPL.jl:97; macro expansion
  80 ./REPL.jl:66; eval_user_input(::Any, ::Base.REPL.REPLBackend)
   80 ./boot.jl:235; eval(::Module, ::Any)
    80 ./<missing>:?; anonymous
     80 ./profile.jl:23; macro expansion
      52 ./REPL[1]:2; myfunc()
       38 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type{B...
        38 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr{F...
       14 ./random.jl:278; rand
        14 ./random.jl:277; rand
         14 ./random.jl:366; rand
          14 ./random.jl:369; rand
      28 ./REPL[1]:3; myfunc()
       28 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinear,...
        3  ./reduce.jl:426; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...
        25 ./reduce.jl:428; mapreduce_impl(::Base.#identity, ::Base.#scalarmax, ::Array{F...

この表示の各行は、コード内の特定のスポット (行番号) を表します。インデントは、入れ子になった関数呼び出しのシーケンスを示すために使用され、よりインデントされた行は呼び出しのシーケンスの中でより深くなります。各行で、最初の「フィールド」は、この行またはこの行で実行される関数で受け取られたバックトレース(サンプル)の数です。 2 番目のフィールドはファイル名と行番号で、3 番目のフィールドは関数名です。ジュリアのコードが変更されるにつれて、特定の行番号が変更される可能性があることに注意してください。この後の話についていくために、この例を自分で実行するのがベストです。

この例では、呼び出される最上位関数がファイル event.jl にあることがわかります。これは、Julia 起動時に REPL を実行する関数です。REPL.jl の 97 行を調べると、eval_user_input() 関数が呼び出される場所であることが分かります。これはREPLで入力した内容を評価する関数です。今は対話的に作業しているので、@profile myfunc() をREPLから入力したときに、これら(訳注: eval_user_input()のことだろうが、なぜ複数?) の関数が呼び出されました。次の行は[@profile`](@ref)マクロで実行されたアクションを反映しています。

最初の行はevent.jlの73行目で80個のバックトレースが取られたことを示していますが、この行自体の演算コストが高いわけでは有りません。: 3行目を見れば、これらのバックトレースの80個すべてが実際にeval_user_inputへの呼び出しの中でトリガされたことが明らかです。実際に時間がかかっている操作を調べるには、コールチェーンをより深く調べる必要があります。

この出力の最初の "重要な" 行はこれです:

52 ./REPL[1]:2; myfunc()

REPL は、REPL で myfunc を定義したという事実を指します。ファイルにmyfuncが定義されたというわけではありません。ファイルを使用していた場合は、(REPLの代わりに)ファイル名が表示されます。[1] は、関数 myfunc がこの REPL セッションで評価された最初の式であることを示しています。myfunc() の 2 行目には rand の呼び出しが含まれており、この行で発生したバックトレースは 52 (80 のうち) でした。その下には、dSFMT.jl 内のdSfmt_fill_array_close_open! の呼び出しがあります。

もう少し下に行くと、下記の行が見つかります:

28 ./REPL[1]:3; myfunc()

myfunc の 3 行目にはmaximumの呼び出しがあり、ここで 28 (80 件中) のバックトレースがカウントされています。その下には、このタイプの入力データに対するmaximum 関数内の時間のかかる処理を実行している、base/reduce.jlのある場所を確認できます。

全体として、乱数の生成は、最大の要素を見つける処理の約2倍のコストがかかると暫定的に結論付けることができます。より多くのサンプルを収集することで、この結果に対する確信を深めることができました:

julia> @profile (for i = 1:100; myfunc(); end)

julia> Profile.print()
[....]
 3821 ./REPL[1]:2; myfunc()
  3511 ./random.jl:431; rand!(::MersenneTwister, ::Array{Float64,3}, ::Int64, ::Type...
   3511 ./dSFMT.jl:84; dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_state, ::Ptr...
  310  ./random.jl:278; rand
   [....]
 2893 ./REPL[1]:3; myfunc()
  2893 ./reduce.jl:270; _mapreduce(::Base.#identity, ::Base.#scalarmax, ::IndexLinea...
   [....]

一般に、ある行でのカウントがN サンプルであった場合、(コンピュータが他のタスクでビジー状態にあるかなど、他のノイズ源を除いて), その値の不確実性は、 sqrt(N)のオーダーであることが期待できます。このルールの主な例外は、実行頻度は低いが、非常に演算コストの高い傾向があるガベージコレクションです。(Julia のガベージコレクタは C で記述されているので、このようなイベントは、以下に説明する C=true 出力モードを使用するか、ProfileView.jl を使用して検出できます。)

これは、デフォルト出力である「ツリー型」ダンプを示しています; 他には、代替案は、入れ子構造に依存せずにカウントを蓄積する「フラット」ダンプです:

julia> Profile.print(format=:flat)
 Count File          Line Function
  6714 ./<missing>     -1 anonymous
  6714 ./REPL.jl       66 eval_user_input(::Any, ::Base.REPL.REPLBackend)
  6714 ./REPL.jl       97 macro expansion
  3821 ./REPL[1]        2 myfunc()
  2893 ./REPL[1]        3 myfunc()
  6714 ./REPL[7]        1 macro expansion
  6714 ./boot.jl      235 eval(::Module, ::Any)
  3511 ./dSFMT.jl      84 dsfmt_fill_array_close_open!(::Base.dSFMT.DSFMT_s...
  6714 ./event.jl      73 (::Base.REPL.##1#2{Base.REPL.REPLBackend})()
  6714 ./profile.jl    23 macro expansion
  3511 ./random.jl    431 rand!(::MersenneTwister, ::Array{Float64,3}, ::In...
   310 ./random.jl    277 rand
   310 ./random.jl    278 rand
   310 ./random.jl    366 rand
   310 ./random.jl    369 rand
  2893 ./reduce.jl    270 _mapreduce(::Base.#identity, ::Base.#scalarmax, :...
     5 ./reduce.jl    420 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
   253 ./reduce.jl    426 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
  2592 ./reduce.jl    428 mapreduce_impl(::Base.#identity, ::Base.#scalarma...
    43 ./reduce.jl    429 mapreduce_impl(::Base.#identity, ::Base.#scalarma...

コードで再帰が使われている場合、"子" 関数の行が合計バックトレースよりも多くのカウントを蓄積する可能性があります。次の関数定義を考えてみましょう:

dumbsum(n::Integer) = n == 1 ? 1 : 1 + dumbsum(n-1)
dumbsum3() = dumbsum(3)

dumbsum3 をプロファイリングし、dumbsum(1) の実行中にバックトレースが取得された場合、バックトレースは次のようになります:

dumbsum3
    dumbsum(3)
        dumbsum(2)
            dumbsum(1)

その結果、親では1カウントのみなのに対して、この子関数は 3 カウントを取得します。「ツリー」表現はこれをより明確にします。そのため、ツリー表現は (特に) 結果を表示する際に最も便利な方法です。

蓄積とクリア

@profileの結果はバッファに蓄積されます。@profileで複数のコードを実行すると、Profile.print()は、それら複数のコードのプロファイルの結果を結合した結果を出力します。これは非常に便利ですが、プロファイルを新たに開始したい場合があります。その場合は、Profile.clear()で、クリアできます。

プロファイル結果の表示を制御するオプション

Profile.print は、これまで説明した以外にも多くのオプションを持っています。全てここで見てみましょう:

function print(io::IO = stdout, data = fetch(); kwargs...)

まず 2 つの位置引数について説明し、後にキーワード引数を説明します:

io – ファイルなどのバッファに結果を保存する。デフォルトではstdout (コンソール) へのプリント出力。
data – 分析したいデータを指定する; デフォルトでは、事前割り当てされたバッファーからバックトレース情報を取り出す Profile.fetch() から取得されま。たとえば、プロファイラーをプロファイリングする場合は、次のように指定できます:
```
data = copy(Profile.fetch())
Profile.clear()
@profile Profile.print(stdout, data) # Prints the previous results
Profile.print()                      # Prints results from Profile.print()
```

キーワード引数には、次の任意の組み合わせを指定できます:

format – 上で紹介したように、バックトレースの表示形式を決定します。関数コールの木構造を示すインデントを用いる :tree(デフォルト) とインデント無しの:flat
C – true の場合、C コードと Fortran コードからのバックトレースが表示されます (通常は除外されます)。 Profile.print(C = true)の紹介例を示すので実行してみてください。この機能は、ボトルネックになっているのが Juliaコードなのか、Cコードの部分なのか判断するのに大変役立ちます。 C = true を設定すると、より長いプロファイルダンプになってしまいますが、ネストの解釈はしやすくなります。
combine – コード行の中には複数の操作が含まれていることがあります。たとえば、s += A[i] には配列の参照(A[i])と加算の両方が含まれています。これらは、生成されたマシンコードでは、別々の行に対応しています。そのため、この行のバックトレース中で2つ以上の異なるアドレスがキャプチャかもしれません。 combine = true オプションはそれらを一緒にまとめます。これはおそらくあなたが通常望む動作でしょう。ただし、combine = false オプションを使えば、一意の命令ポインターごとにに出力を生成することもできます。
maxdepth – :tree 形式での maxdepth よりさらに大きい値を持つ深さで表示するフレームを制限します。
sortby – :flat 形式での表示順序を制御します。:filefuncline (デフォルト) はソースファイルによるソート、:count は収集されたサンプルの数の順番でのソートです。
noisefloor – サンプル数のノイズフロアをヒューリスティックに指定します。ノイズフロアより下のフレームは表示が制限されます(フォーマット:treeにのみ適用されます)。これを試す際の推奨値は 2.0 です (デフォルトは 0)。このパラメーターは、n <= ノイズフロア * √N のサンプルを非表示にします。ここで n は、この行のサンプルの数で、N は呼び出し先のサンプルの数です。
mincount – ここで指定した値よりも小さいオカレンスのフレームを制限します。

ファイル/関数名は、(...) を使って切り捨て表示されることがあります。また、インデントは先頭で +n で切り捨てられます。ここで n は挿入される追加のスペースの数です。深くネストされたコードの完全なプロファイルが必要な場合は、IOContextで広い「表示サイズ」を使用してファイルに保存することをお考えめします:

open("/tmp/prof.txt", "w") do s
    Profile.print(IOContext(s, :displaysize => (24, 500)))
end

構成・設定

@profile はバックトレースを蓄積するだけです。実際の分析は、Profile.print()を呼び出したときに行われます。実行時間の長い計算では、バックトレースを格納するために事前に割り当てられたバッファがいっぱいになる可能性があります。その場合、バックトレースは停止しますが、プロファイル対象の計算自体は続行されます。その結果、いくつかの重要なプロファイリングデータを見逃す可能性があります (その場合は警告が表示されます)。

以下で、関連するパラメータを取得および構成できます:

Profile.init() # returns the current settings
Profile.init(n = 10^7, delay = 0.01)

n は、格納できる命令ポインターの合計数で、デフォルト値は 10^6 です。一般的なバックトレースが 20 の命令ポインタである場合は、50000 バックトレースを収集できるため、統計的な不確実性が 1% 未満であることを示唆しています。これは、ほとんどのアプリケーションで十分でしょう。

delayは、要求された計算を実行するための複数スナップショットの間でJuliaが取得する時間長を秒単位で表記するものですが、前文のような状況であればその結果、このdelayの修正が必要になる可能性が高くなります。非常に長い時間実行されるジョブでは、頻繁なバックトレースは必要ない場合があります。デフォルトの設定は'遅延 = 0.001'です。もちろん、遅延を減らすだけでなく、遅延を増やすことができます。ただし、遅延がバックトレース (作成者のラップトップで約 30 マイクロ秒) を取るのに必要な時間に近くなると、プロファイリングのオーバーヘッドが大きくなります。

メモリ割り当て分析

パフォーマンスを向上させる最も一般的な手法の 1 つは、メモリ割り当てを減らすことです。メモリ割り当ての合計量は@timeと@allocatedで測定することができ、メモリ割り当てをトリガする特定の行は、多くの場合、これらの行で発生するガベージコレクションによる演算コストを介してプロファイリングから推測することができます。ただし、コード行ごとに割り当てられるメモリの量を直接測定する方が効率的な場合もあります。

メモリ割り当てを 1 行ずつ測定するには、--track-allocation=<setting>コマンドラインオプションをついけてJulia を起動します。選択可能なオプションは、none (デフォルト値。メモリ割り当てを測定しない) 、user(Juliaのコアコードを除く、Juliaコードの各行におけるメモリ割り当てを測定する), all(全Juliaコードの各行でメモリ割り当てを測定)です。 Julia終了時、各ソースファイルのファイル名の後に.memが付加されたテキストファイルに書き込まれます。出力先は、ソースファイルと同じディレクトリです。各行には、合計バイト数が一覧表示されます。Coverage パッケージには、基本的な分析ツール、例えばメモリ割り当てのバイト数での行ソートなど、が含まれています。

結果を解釈する際には、いくつか重要な詳細情報があるので気をつけてください。 --track-allocation=user で実行した場合、REPL から直接呼び出される関数の最初の行には、REPLからの関数コール自体に含まれメモリ割り当ての情報が示されます。さらに重要なのは、ジュリアのコンパイラの多くはジュリアで書かれているので(そしてコンパイルは通常メモリ割当が必要なので)、JIT コンパイルによってメモリ割り当てカウントが追加されるということです。推奨される手順は、すべての分析したいすべてのコマンドをを実行して強制的にコンパイルしておき、Profile.clear_malloc_data()を呼び出して、すべての割り当てカウンタをリセットすることです。最後に、目的のコマンドを実行し、ジュリアを終了して '.mem'ファイルの生成をトリガーします。

外部のプロファイリングツール

現在、Juliaは外部プロファイリングツールとしてIntel VTune、OProfile、perfをサポートしています。

選択したツールに応じて、Make.userファイル内で、USE_INTEL_JITEVENTS、USE_OPROFILE_JITEVENTS、USE_PERF_JITEVENTS などを1に設定してコンパイルしてください。複数のフラグがサポートされています。

Julia を実行する前に、環境変数 ENABLE_JITPROFILING を 1 に設定します。

これで、あなたはこれらのツールを使用する多数の方法を手に入れました。たとえば、OProfile を使用すると、簡単な記録をすることができます:

>ENABLE_JITPROFILING=1 sudo operf -Vdebug ./julia test/fastmath.jl
>opreport -l `which ./julia`

または perfとにたやり方で:

$ ENABLE_JITPROFILING=1 perf record -o /tmp/perf.data --call-graph dwarf ./julia /test/fastmath.jl
$ perf report --call-graph -G

あなたのプログラムついて測定を行う方法は他にもたくさんあり、興味深いです。包括的なリストを見たければ,Linux perfの例のページを読んでください。

実行ごとにperfは、 perf.data ファイルを保存し、小規模なプログラムの場合でも非常に大きなファイルを保存できることを覚えておいてください。また、perf LLVMモジュールは、一時的にデバッグオブジェクトを~/.debug/jitに保存しますから、そのフォルダを頻繁にクリーンアップすることを忘れないでください。