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

## はじめに

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

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

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

## PerfとHotspot

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

Hotspotのインストール

```
sudo apt install hotspot
```

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

```cr: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が立ち上がります。

![Screenshot from 2023-12-03 13-35-01.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/f5c78965-b40e-53ea-9d78-c22e2c972e61.png)

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

![Screenshot from 2023-12-03 13-38-29.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/cf4dd6a0-848f-04c1-9d23-c1896cb9c2b5.png)

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

![Screenshot from 2023-12-03 13-40-16.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/5ac0d365-bf24-ff80-78d8-d7f2617effaf.png)![Screenshot from 2023-12-03 13-40-37.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/be41a9e6-1fc1-682a-0dbc-ae570f62247d.png)

Frame Graph も taraiのみです。

![Screenshot from 2023-12-03 13-41-40.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/35a6e344-ea0c-ec73-aeb6-98a1c35d895a.png)

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

![Screenshot from 2023-12-03 13-49-05.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/6cc34766-57b8-d19b-dff4-f2c1d360ce04.png)

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

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

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

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

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

```cr:hello.cr
puts "hello"
```

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

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

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/144608/06c33797-eb9b-07b3-2bd5-7a7ec99dffc5.png)

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

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

以上、自分もわからないことだらけですが、年に２，３回はCrystalで書いたコードのプロファイルを取りたいと思うことがあります。そのたびごとに調べ直しが発生するので、記事にまとめました。コードが遅い原因を調べる時、とくに[Crystalのコードが原因なのか、それとも外部のCの関数を呼んでいて、その関数が遅いことが原因なのか調べたりする](https://forum.crystal-lang.org/t/ruby-out-performs-crystal-significantly-on-this-numerical-algorithm/5538/10)などに威力を発揮します。

この記事は以上です。


参考文献：

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

https://techlife.cookpad.com/entry/2020/12/26/131858