Clozure CLでプロファイラを利用する

2019-05-02 19:51追記

プロファイル取得用のイメージを作成する手順がありますが手順を間違えると処理の実行のたびにfaslのダンプが行われて計測結果を汚すので注意してください。イメージ作成手順にも追記します。

TL;DR

 Clozure CLの以下ドキュメントに書いてある通りです(本記事では素のCCLではなくRoswell上での利用方法が書かれています)。

ccl.clozure.com

動機

 PortAudio/cl-portaudioを用いてCommon Lispサウンドプログラミング実験をしています(どんなことをしているのかはざっくりこちらのスライド参照。いつか記事かなにかにしたい)。

github.com

 ある程度音が鳴らせるようになってきたので、ちょっと複雑な音を鳴らしてみようと思いました。が、プログラムの実行速度が遅いのかバッファアンダーランが発生して音がぶちぶちに切れてしまい、これでは音楽つくるどころではありません。しかしここまで大きく育ったプログラムのどこがボトルネックか、ぼくにはパッとわかりませんでした。

 なのでプロファイラを用いてどの処理が重いのかとても知りたいです。

 ちなみに普段使っている処理系はClozure CLなので、SBCLに組込みのプロファイラは使えません(さらに言うと何かがおかしいのかpukunuiをSBCLでロードすると型エラーになったような気がする)。

環境や準備

環境

使うもの

手順

 ここではサンプル用のコードを説明用に用意せず、pukunuiをそのまま使って手順を説明します。しかし使うだけならそんなに難しくないはず…。

pukunui関係準備

 Pukunuiではcl-portaudioを通してlibportaudio2を利用しますので、aptでインストールしてください。Pukunui本体も.roswell/local-projectsとかに置いている前提です。

プロファイルを取るための準備

 Oprofileでは起動前・起動後の対象を指定してプロファイラを起動し、その実行中の情報をOSを介して取得するしくみです。対象に指定できるのは以下です:

  • システム全体
  • 指定したpidのプロセス
  • 引数に指定した実行可能ファイル(とその引数)を起動したプロセス

 今回はpidを指定してプロファイルを取得します。まずCCLでしておくべきことは

  1. プロセス内のシンボル一覧をファイルに保存
  2. 上記シンボル一覧と関数が対応する処理系のイメージを作成

です。ros use ccl-binが済んでいれば簡単なのでやってみましょう。

$ ros run
Clozure Common Lisp Version 1.11.5/v1.11.5  (LinuxX8664)

For more information about CCL, please see http://ccl.clozure.com.

CCL is free software.  It is distributed under the terms of the Apache
Licence, Version 2.0.

;; シンボルテーブルを保存
? (require :elf)  ; 必要なパッケージをインポート
ELF
? (ccl::write-elf-symbols-to-file "elf-symbols")  ; `elf-symbols`にシンボルが書き出される

;; `elf-symbols`に関数が対応した処理系イメージを作成し終了
? (save-application "pukunui-prof-image" :prepend-kernel "elf-symbols")
$ 

2019-05-02 19:54追記

ちなみにライブラリのasdf:load-systemや計測に必要なLispプログラムのloadccl:save-application前にやっておきましょう。「ライブラリロードはイメージ作成前に、プログラムのロードは計測直前に」などとするとClozure CLではロードしたプログラムのfaslへのダンプ処理が計測対象実行の度に走るようです。これによりCCL::FASL-DUMP実際のコードでは使っていない処理が計測結果に登場してプロファイリングを困難にします。ご注意ください。

プロファイルを取る

 ここからはターミナルを複数立ち上げて作業します。

 まずCCLの処理系を先程のイメージで起動します。Roswell越しにCCLにオプションを渡し、イメージを指定します。その後、プロファイルを取得する前の準備(プログラムのロードや初期化)をします。 2019-05-02 19:54追記 プログラムのロード等はイメージ作成前に行ってください

$ ros run -- -I ./pukunui-prof-image
...

;; プログラムの初期化 (ここではpukunuiのロードと音を鳴らすプログラムの準備)
? (ql:quickload :pukunui)
PUKUNUI
? (load (asdf:system-related-pathname :pukunui "examples/04-seq.lisp"))
#P"pukunui/examples/04-seq.lisp"

 これでpukunuiの初期化は完了です。スタートする前に、プロファイラを別ターミナルで起動しておきます。

$ ps aux | grep lx86cl64   # 上で起動したCCLのpidを調べる
$ sudo operf --pid xxxx
...

 プロファイルを取得するためにCCLのREPLで(pukunui:start)を打ちます。カービィの音が鳴り終わったら、プロファイラのほうでCtrl-xを押してプロファイラを止めます。プロファイラを止めるとoprofile_dataというディレクトリができており、そこにプロファイル結果が入っています。サマリを見てみましょう。このとき、実行したCCLのイメージを指定すると内部のシンボル名が何回呼ばれたかが表示されます。

$ opreport -l pukunui-prof-image  | head
Using /home/grey/Dropbox/code/pukunui/examples/oprofile_data/samples/ for samples directory.

WARNING! Some of the events were throttled. Throttling occurs when
the initial sample rate is too high, causing an excessive number of
interrupts.  Decrease the sampling frequency. Check the directory
/home/grey/Dropbox/code/pukunui/examples/oprofile_data/samples/current/stats/throttled
for the throttled event names.


WARNING: Lost samples detected! See /home/grey/Dropbox/code/pukunui/examples/oprofile_data/samples/operf.log for details.
CPU: Intel Ivy Bridge microarchitecture, speed 3900 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               symbol name
4434      7.9773  pukunui-image            CCL::FASL-DUMP-EPUSH
4358      7.8405  pukunui-image            RANDOM
2882      5.1850  pukunui-image            CCL::FASL-DUMP-DISPATCH
2780      5.0015  pukunui-image            CCL::%BIGNUM-RANDOM
2553      4.5931  pukunui-image            CCL::%STRING-HASH-FOLDING-CASE
1948      3.5047  pukunui-image            <Compiled-function.(:INTERNAL.CCL::GET-LOCAL-VALUE.CCL::ARGUMENTS-AND-LOCALS).(Non-Global)..0x300000A0412F>
1815      3.2654  pukunui-image            FLOAT-SIGN

 なにか警告がでていますが、全イベントが取得できなかったみたいです。まだよくわかってないですが、改善の余地があるということなのでしょう。

所感

 プロファイルを取得するときは本当に計測したい部分でのみプロファイラを起動(=プロファイルデータを集める)しましょう。pukunuiは例えば信号処理プログラムですが、最初はライブラリの初期化を含めて計測してしまったため、信号処理には関係ない(本来の計測対象ではない)処理が上位に出てきてしまいます。

 結果を見ている感じ、Pukunuiに関してはたぶん自前実装オブジェクトシステムもどきのあたりがボトルネックになってそうでした(ccl:%string-hash-folding-caseとかあるので。自前オブジェクトは型とメソッドの対応表がハッシュテーブルに入っている)。あとRANDOMってなんじゃい(上のプロファイル結果のプログラム 06-applications.lispでは使っていない)。Pukunuiが変な挙動をしているのかもしれません。

 やはりKiwi Lightweight Object Systemが必要か…。

所感追記 (2019-05-02 19:54)

 上のプロファイル結果にCCL::FASL-DUMP-EPUSHなどが現れていますが、これはpukunuiのコードで行われている処理ではありません。上で述べたようにプロファイリング用イメージの作成手順を誤ると走ってしまうようです(詳細な原因は不明)。

 また、randomexamples/06-applications.lispを用いていれば登場しないはずですので、計測用イメージの作成ミスかもしれません。計測の準備は注意ぶかく行いましょう。