PerfとHotspotを使ってCrystalのプロファイルをとる

はじめに

今日もCrystalの薄いネタです。よくわかってない内容なので間違ってたらコメント欄で解説してください。

Crystalのプログラムが遅いとき

自分が書いたスクリプトが妙に遅いときがあります。その場合、まずは time コマンドなどで実行時間を計測しますが、やっぱり遅いなと思う場合があります。その場合はプロファイルをとるとその理由がわかることがあります。

PerfとHotspot

プロファイルをとるツールはたくさんあります。今回は、Perf で記録をとり、Hotspotというツールでこれを閲覧します。プロファイルのとり方はかなりOSに依存すると思うので、それぞれのOSの標準的な方法を使えばいいと思います。

Hotspotのインストール

sudo apt install hotspot

まずは計測対象のファイルを用意します。今回は竹内関数にしてみましょう。

takeuchi.cr

def tarai(x, y, z)
  if x <= y
    y
  else
    tarai(tarai(x - 1, y, z),
          tarai(y - 1, z, x),
          tarai(z - 1, x, y))
  end
end

tarai(14, 7, 0)

ビルドします。

crystal build takeuchi.cr

本当はデバッグフラグつけた方がいいのかも。（でも今回はつけなくても大丈夫っぽいですが）

crystal build --debug takeuchi.cr

Perf コマンドで計測をします。

sudo perf record ./takeuchi

サンプリングレートが低くてあまり有為な結果が出ない場合は、周波数を上げることができます。

sudo perf record -F max ./takeuchi

結果を見ます。結果のファイルは perf.data というファイル名で保存されています。

sudo hotspot

hotspotの起動で、sudo を避けたい場合は、ターミナルからhotspotを起動したくない場合は、先に perf.data を読み込めるようにしておきます。

sudo chmod +r perf.data
hotspot

とすればよいです。すると GUIが立ち上がります。

上の画面のように File perf.data is not readable が表示されている場合は、ファイルに読み込み権限が付与されていない状態で、hotspotを起動しています。

今回は、Bottom Up も Top Down もないですね。圧倒的にtaraiです。

Frame Graph も taraiのみです。

Caller/Callee にすると、行情報を見ることができるようです。

今回はあんまり良い例にはなりませんでした。

もう少し複雑な例として、Crystalのビルドの perf をとってみましょう。

（そんな必要はないかもしれませんが）一応Crystal本体をデバッグビルドしてみます。

git clone https://github.com/crystal-lang/crystal
cd crystal
make debug=1

簡単なCrystalのスクリプトを用意します。

hello.cr

puts "hello"

sudo perf record -F max crystal/bin/crystal build hello.cr # dubug build のクリスタル
sudo chmod +r perf.data
hotspot perf.data

すると、こんな感じで、libgc が時間をとっていることがわかります。繰り返しの操作を行う時に、調子に乗ってオブジェクトをたくさん生成するとガーベッジコレクションで意外と時間を取ることが多い印象がありますから、パフォーマンスを気にする場合は、とくに注意する必要があると思います。

to_s はさまざまなメソッドの to_s がまとめて計測されてしまっているようです。このあたりがCrystalのプロファイルを取る時の難しさでしょうか。next_token が時間をとっているのも興味深いですね。

ちなみに、初回起動だとLLVMが時間をとっていたりしました。画面の結果にはLLVMは表示されていませんが、最初はLLVMが呼ばれて何回もコンパイルすると呼ばれなくなる（キャッシュを使っている？）みたいな機構がなにかあるのかもしれません。（詳しくないのでわかりません。すみません。）

以上、自分もわからないことだらけですが、年に２，３回はCrystalで書いたコードのプロファイルを取りたいと思うことがあります。そのたびごとに調べ直しが発生するので、記事にまとめました。コードが遅い原因を調べる時、とくにCrystalのコードが原因なのか、それとも外部のCの関数を呼んでいて、その関数が遅いことが原因なのか調べたりするなどに威力を発揮します。

この記事は以上です。

参考文献：

竹内関数の実装はこちらのものを利用しました。