Common Lispファイルでプロファイリングする(SBCL)
プログラムを作っていると、どこの部分が時間がかかっているか調べたいときがある。そういうとき使うツールがプロファイラというもので、速度が遅い関数を特定できれば、そこをチューンアップしてプログラム全体の性能を改善するための手助けになる。
ここではCommon LispのSBCL(Steel Bank Common Lisp)に標準装備されている「sb-sprof」というプロファイラで速度を測ってみた。
なお、SBCLのプロファイラにはもうひとつsb-profileというのもあるらしい。自分が調べたい呼び出しを狙い撃ちで指定できるようだが、使い方がよくわからなかった。
プロファイラを使う
自分の作ったプロジェクトで、csvファイルを読み込んで加工して表示する一連のプログラムがある。ひどいプログラムなので公開は差し控えるが、このプログラムは45個の関数を持ち、src/apro.lispに入っている。今回、遅い関数はどれか調べてみた。
プロジェクト名はaproという。
$ cd ~/work/sbcl $ ls myapp myapp2 apro $ cd apro $ ls README.markdown db apro-test.asd apro.asd run.ros src tests $ ros run
(ここからはSBCL内。先頭の*はプロンプト。) * (ql:quickload :apro) To load "apro": Load 1 ASDF system: apro ; Loading "apro" . (:APRO) * (require :sb-sprof) ; プロファイラの読み込み ("SB-SPROF") * (sb-sprof:start-profiling) ; プロファイラによる計測開始 * (progn (apro:prepare-tables) (apro:rebuild)) ; 時間計測するプログラム APRO::DONE * (sb-sprof:stop-profiling) ; 計測終了 * (sb-sprof:report) ; レポート出力 Number of samples: 62 Sample interval: 0.01 seconds Total sampling time: 0.62 seconds Number of cycles: 0 Sampled threads: #<SB-THREAD:THREAD "main thread" RUNNING {9D5E329}> Callers Total. Function Count % Count % Callees ------------------------------------------------------------------------ 22 35.5 SB-KERNEL:%CONCATENATE-TO-STRING [5] 22 35.5 22 35.5 SB-KERNEL:UB32-BASH-COPY [1] ------------------------------------------------------------------------ 7 11.3 (LAMBDA (APRO::Y) :IN APRO::WRITE-TO-DAILY) [192] 2 3.2 APRO::MATCH-PAIRS [171] 9 14.5 9 14.5 (FLET SB-IMPL::FAST-NTHCDR :IN NTHCDR) [2] ------------------------------------------------------------------------ 1 1.6 SB-UNIX:UNIX-STAT [169] 7 11.3 "foreign function interrupt_handle_pending" [79] 8 12.9 8 12.9 "foreign function __kernel_vsyscall" [3] ------------------------------------------------------------------------ （略） ------------------------------------------------------------------------ 1 1.6 SB-INT:SIMPLE-EVAL-IN-LEXENV [33] 0 0.0 1 1.6 APRO::WRITE-TO-MONTHLY [193] 1 1.6 REMOVE-IF-NOT [19] ------------------------------------------------------------------------ Self Total Cumul Nr Count % Count % Count % Calls Function ------------------------------------------------------------------------ 1 22 35.5 22 35.5 22 35.5 - SB-KERNEL:UB32-BASH-COPY 2 9 14.5 9 14.5 31 50.0 - (FLET SB-IMPL::FAST-NTHCDR :IN NTHCDR) 3 8 12.9 8 12.9 39 62.9 - "foreign function __kernel_vsyscall" 4 3 4.8 25 40.3 42 67.7 - SB-KERNEL:%CONCATENATE-TO-STRING 5 3 4.8 3 4.8 45 72.6 - (FLET "CLEANUP-FUN-7" :IN SB-IMPL::REFILL-INPUT-BUFFER) 6 1 1.6 10 16.1 46 74.2 - REMOVE-IF-NOT 7 1 1.6 2 3.2 47 75.8 - EQL 8 1 1.6 1 1.6 48 77.4 - SB-KERNEL::%TYPE-INTERSECTION （略） 192 0 0.0 1 1.6 62 100.0 - APRO::RANGE-YMD-STRING 193 0 0.0 1 1.6 62 100.0 - APRO::WRITE-TO-MONTHLY ------------------------------------------------------------------------ 0 0.0 elsewhere #<SB-SPROF::CALL-GRAPH 62 samples {AAACE21}> *
プロファイラの使い方は以下の通り。
(require :sb-sprof)でプロファイラを読み込む。(sb-sprof:start-profiling)を実行してプロファイラを起動する。- なにか実行時間を計測したいプログラムを実行させる。
- 計測が終了したら、
(sb-sprof:stop-profiling)を実行する。 (sb-prof:report)でレポート出力する。
レポートは前半と後半の2部に分かれており、読み取り方はこれから勉強する。
