性能測定

目次

Profile モジュールはコードの性能向上を支援するツールを提供します。このツールは実行されているコードの性能を計測し、各行の実行にかかった時間を分かりやすい形で出力します。最適化の対象となる「ボトルネック」を見つけるために最もよく使われます。

Profile は「サンプリングプロファイラ」あるいは「統計的プロファイラ」と呼ばれるものを実装します。これは任意のタスクを実行しているプログラムのバックトレースを定期的に取得することで動作します。バックトレースは現在実行中の関数と行番号、そしてその行にいたるまでの関数の呼び出し履歴を持つので、その時点における実行状態の "スナップショット" と言えます。

もしコードの特定の行を実行するのに多くの時間が費やされているなら、その行は取得されたバックトレースの中で頻繁に表れるはずです。言い換えれば、ある行のコスト ──正確には、その行が呼び出す全ての関数を含めたコスト── は、その行がバックトレースに表れる頻度に比例します。

サンプリングプロファイラはバックトレースを一定の間隔で取得するので、コードの実行にかかった時間を一行ごとに完全な形で示すことはできません。(間隔は Unix では 1 ms ごと、Windows では 10 ms ごとです。ただし OS の負荷に影響を受けます)。さらに、後述するように、サンプルは全実行時間のごく一部から収集されるので、統計的ノイズが避けられません。

こういった制限はあるものの、サンプリングプロファイラには大きな利点があります:

こういった理由により、他のプロファイラを試す前に組み込みのサンプリングプロファイラを最初に使うことが推奨されます。

基本的な使い方

簡単なテストケースから始めます:

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

プロファイルするコードを最初に一度実行するようにしてください (JIT コンパイラをプロファイルしたい場合は除きます):

julia> myfunc() # 一度実行してコンパイルを強制する。

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

julia> using Profile

julia> @profile myfunc()

プロファイルの結果を見るためグラフィカルなブラウザは何種類かあります。次に示すのは FlameGraphs.jl を使った可視化プログラムであり、それぞれ異なるユーザーインターフェースを持ちます:

PProf.jl は完全に独立したプロファイル可視化アプローチを採用しており、外部の pprof ツールを利用します。

ただここでは、標準ライブラリに内蔵されるテキストベースの表示を使います:

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...

出力の各行がコード中の計測点 (行番号) を表します。インデントは入れ子になった関数呼び出しを表し、呼び出し階層の下の方で呼び出されている関数には大きなインデントが付きます。各行の最初のフィールドはその行あるいはその行が呼び出す関数を実行中に取得されたバックトレース (サンプル) の個数です。二つ目のフィールドはファイル名と行番号であり、三つ目のフィールドは関数の名前です。Julia のコードが変更されると行番号も変化するので、以降の例は自分で実行することを推奨します。

この例では、トップレベルで実行される関数が event.jl というファイルにあることが分かります。これは Julia を起動したときに呼ばれる関数であり、REPL を実行します。また REPL.jl の 97 行目を見れば、eval_user_input() という関数が呼ばれているのが分かるでしょう。これは REPL に入力した文字列を評価する関数であり、今の例では対話的に入力を行っているので、@profile myfunc() と入力したときに eval_user_input() 関数が呼び出されます。以降の行は @profile マクロが行う処理を表します。

出力の最初の行からは、event.jl の 73 行目で 80 個のバックトレースが取得されたことが分かります。しかし、event.jl の 73 行目にはそれほど時間を取られていないことも分かります: 例えば出力の 3 行目が示すように、eval_user_input を呼び出している間にも 80 個のバックトレースが取得されているからです。本当に時間がかかっている処理がどれなのかを理解するには、呼び出しの履歴をさらに細かく見る必要があります。

出力の中で最初の "重要な" 行は次の行です:

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

REPL は myfunc がファイルではなく REPL で定義された事実を表しています。もしファイルに書き込んでから読み込めば、この部分にファイル名が表示されます。[1] は myfunc 関数の定義が REPL セッションで最初に評価された式であることを表します。myfunc の二行目には rand の呼び出しがあり、80 個あるバックトレースの 52 個がここで取得されています。rand の下には dSFMT.jl からの dsfmt_fill_array_close_open! の呼び出しがあります。

そこから少し下ると、次の行があります:

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

myfunc の三行目は maximum の呼び出しであり、この行で 80 個のあるバックトレースの 28 個が取得されたことを表しています。その下を見ると、この例の入力データ (Array{Float64,3} 型の値) に対する maximum 関数において時間のかかる処理を行っているのが reduce.jl であることが分かります。

まとめると、乱数の生成には最大要素の探索より二倍程度のコストがかかるようだと暫定的に結論できそうです。サンプルを多く収集すれば確度を高められます:

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)

このため、呼び出し側の dumbsum3 はカウントを一つしか得ないにもかかわらず、末端の再帰関数 dumbsum は三つのカウントを得ます。このような場合にはツリー型の表示の方がずっと状況を理解しやすいので (その他にも理由はありますが)、プロファイルの結果はツリー型の表示で見るのが一番でしょう。

結果の蓄積と消去

@profile の結果はバッファに蓄積されます。そのため @profile でコードを何度かプロファイルすると、Profile.print() はそれらを足し合わせた結果を表示します。これは非常に便利な機能ですが、最初からやり直したい場合もあるでしょう: そのときは Profile.clear() を使ってください。

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

Profile.print のオプションにはこれまでに説明していないものも存在します。この関数の完全な宣言を示します:

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

まず二つの位置引数を説明し、キーワード引数はその後に説明します:

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

横幅が足りないとファイルや関数の名前が ... と省略されたり、インデントが +n と表されたりします (n は横幅が足りていたら挿入されていたはずの空白の個数を表します)。深くネストされたコードの完全なプロファイルが必要なら、IOContext で広い displaysize を指定した上でプロファイルをファイルに保存すると取得できます:

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

プロファイラの設定

長く実行される計算では、バックトレースを保存するバッファを事前にアロケートしておいて、そのバッファに収まる分だけバックトレースを記録することもできます。バッファが埋まった時点でバックトレースの記録は止まり、以降は実行だけが続きます。実行の途中でバッファが満杯になると重要なプロファイルデータを見逃す可能性があります (出力するときに警告が起きます)。なお @profile はバックトレースを蓄積するだけで、解析は Profile.print() を呼んだときに起こります。

プロファイラの設定に関連するパラメータは次のように確認・設定します:

Profile.init() # 現在の設定が返る。
Profile.init(n = 10^7, delay = 0.01)

n は保存できる命令ポインタの総数で、デフォルトは 10^6 です。計測しているプログラムの典型的なバックトレースが 20 個の命令ポインタを含むなら、これは 50000 個のバックトレースを収集できることを意味します。このとき統計的な不正確さは 1% 未満と見積もられるので、たいていのアプリケーションではこれで十分でしょう。

一方で、delay には n より多い頻度で調整が必要になるでしょう。delay は計算の実行中に Julia がスナップショットを取る間隔を指定します (単位は秒)。長い計算ではバックトレースを頻繁に取得するには及ばないかもしれません。デフォルトの設定は delay = 0.001 です。もちろん delay は大きくするだけではなく小さくもできます。ただし、delay の値がバックトレースを取得する時間 (筆者の PC では 30 マイクロ秒ほど) に近づいていくと、プロファイルのオーバーヘッドが無視できなくなります。

メモリのアロケートの解析

性能を向上させるために最もよく使われるテクニックの一つがメモリのアロケートの削減です。アロケートされたメモリの総量は @time や @allocated で計測でき、アロケートが起こっている行はプロファイルでガベージコレクションの処理時間に注目することで多くの場合予測できます。しかし、各行がアロケートするメモリ量を直接計測した方が効率的な場合もあります。

コマンドライン引数 --track-allocation=<setting> を付けて Julia を起動するとメモリのアロケートを行ごとに計測できます。<setting> には次のいずれかを指定します:

アロケートはコンパイルされるコードの各行で計測されます。Julia を終了すると、蓄積された結果がそれぞれのファイル名の最後に .mem を付けたファイルに書き込まれ、そのファイルの各行がアロケートしたメモリの総バイト数を示します。Coverage.jl パッケージには簡単な解析ツールが含まれており、例えばアロケートされたメモリのバイト数でソースコードの行をソートするといったことができます。

アロケートの計測結果の解釈では、気を付けるべき重要な点がいくつかあります。user 設定を使うと、REPL から直接呼ばれる全ての関数の最初の行に REPL のコードに由来するアロケートが見えます。また JIT コンパイルがあるとアロケートのカウントがさらに大きく増加します。これは Julia のコンパイラの大部分が Julia で書かれているためです (コンパイルにはメモリのアロケートが必要です)。最初に解析する関数を実行して JIT コンパイルを確実に起こしてから Profile.clear_malloc_data() を呼ぶことで、アロケートのカウントをリセットしてから計測を行うことが推奨されます。そうしてから計測したいコマンドを実行して Julia を終了すれば .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

プログラムに関して計測できる興味深い項目はいくつもあります。http://www.brendangregg.com の Linux perf examples に様々な例が載っています。

perf が実行ごとに作成する perf.data というファイルは、計測しているのが小さなプログラムであっても非常に大きくなる場合があることを頭の片隅に置いておいてください。また perf LLVM モジュールは一時的なデバッグオブジェクトを ~/.debug/jit に保存するので、このフォルダは定期的に削除した方がよいでしょう。

広告
このページの文章はテキストゆれないくんを使って校正されました。