Clozure CLでプロファイラを利用する
2019-05-02 19:51追記
プロファイル取得用のイメージを作成する手順がありますが手順を間違えると処理の実行のたびにfaslのダンプが行われて計測結果を汚すので注意してください。イメージ作成手順にも追記します。
TL;DR
Clozure CLの以下ドキュメントに書いてある通りです(本記事では素のCCLではなくRoswell上での利用方法が書かれています)。
動機
PortAudio/cl-portaudioを用いてCommon Lispでサウンドプログラミング実験をしています(どんなことをしているのかはざっくりこちらのスライド参照。いつか記事かなにかにしたい)。
ある程度音が鳴らせるようになってきたので、ちょっと複雑な音を鳴らしてみようと思いました。が、プログラムの実行速度が遅いのかバッファアンダーランが発生して音がぶちぶちに切れてしまい、これでは音楽つくるどころではありません。しかしここまで大きく育ったプログラムのどこがボトルネックか、ぼくにはパッとわかりませんでした。
なのでプロファイラを用いてどの処理が重いのかとても知りたいです。
ちなみに普段使っている処理系はClozure CLなので、SBCLに組込みのプロファイラは使えません(さらに言うと何かがおかしいのかpukunuiをSBCLでロードすると型エラーになったような気がする)。
環境や準備
環境
- Ubuntu 18.04
- Clozure Common Lisp Version 1.11.5/v1.11.5 (LinuxX8664)
使うもの
手順
ここではサンプル用のコードを説明用に用意せず、pukunuiをそのまま使って手順を説明します。しかし使うだけならそんなに難しくないはず…。
pukunui関係準備
Pukunuiではcl-portaudio
を通してlibportaudio2
を利用しますので、aptでインストールしてください。Pukunui本体も.roswell/local-projects
とかに置いている前提です。
プロファイルを取るための準備
Oprofileでは起動前・起動後の対象を指定してプロファイラを起動し、その実行中の情報をOSを介して取得するしくみです。対象に指定できるのは以下です:
- システム全体
- 指定したpidのプロセス
- 引数に指定した実行可能ファイル(とその引数)を起動したプロセス
今回はpidを指定してプロファイルを取得します。まずCCLでしておくべきことは
- プロセス内のシンボル一覧をファイルに保存
- 上記シンボル一覧と関数が対応する処理系のイメージを作成
です。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プログラムのload
はccl: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のコードで行われている処理ではありません。上で述べたようにプロファイリング用イメージの作成手順を誤ると走ってしまうようです(詳細な原因は不明)。
また、random
もexamples/06-applications.lisp
を用いていれば登場しないはずですので、計測用イメージの作成ミスかもしれません。計測の準備は注意ぶかく行いましょう。