【Common Lisp】
コードのパフォーマンスを、
time と sb-sprof で調べる
（SBCL）

by
  • SBCLにはtimeとsb-sprofという2つの計測ツールが同梱されており、コードのどこが遅いかを実測で特定できます。
  • timeは実行時間とメモリ確保量を出力する組み込み関数で、改善前後の比較に使います。
  • sb-sprofは統計的プロファイラで、一定間隔でコールスタックをサンプリングし、時間を多く消費している関数を割合で示します。
  • appendによる末尾追加のようなO(n²)の処理は、pushとnreverseを組み合わせたO(n)に変えるだけで、実行時間とメモリ確保量が大幅に改善されます。

関連記事

1. timeとsb-sprof とは

Common Lisp でコードが遅いときに、勘で「どこが重いか」を追ってもなかなか直せません。

Common Lisp パフォーマンス調査 time と sb-sprof で実測する STEP 1 time 全体時間を確認 STEP 2 sb-sprof 重い関数を特定 STEP 3 改善 アルゴリズム変更 STEP 4 time 改善前後を比較 勘で当てるより実測が速い

SBCL には、timeという組み込みのパフォーマンス測定関数と sb-sprof という統計的プロファイラが同梱されていて、どの関数で時間を使っているかを実測できます。

パフォーマンス調査の基本的な流れは、

  1. time で全体の実行時間を確認する
  2. sb-sprof でどの関数が上位に来るかを見る
  3. 上位の関数を改善する（アルゴリズム変更、不要な cons を減らす、など）
  4. 再び time で改善前後を比較する

2. timeで実行時間を測定する

sb-sprof を使う前に、time 関数で全体の実行時間を測っておきます。
time は SBCL 組み込みで、実行時間とメモリ確保量を出力します。

(time (your-function parameters))Code language: Lisp (lisp)

たとえば、リストの末尾に要素を追加し続けるパターンがあります。
ここでは、build-list-naive と build-list-fast の計測を比べてみます。

;; O(n²) — append を使って末尾に追加し続ける
(defun build-list-naive (n)
  (let ((result '()))
    (dotimes (i n result)
      (setf result (append result (list i))))))

;; O(n) — push で先頭に積んで最後に nreverse する
(defun build-list-fast (n)
  (let ((result '()))
    (dotimes (i n)
      (push i result))
    (nreverse result)))Code language: Lisp (lisp)

append を使う版は、第 1 引数のリスト全体をコピーしてから第 2 引数を繋ぐため、result が 0, 1, 2, … と伸びるにつれコピーコストも増えるので、合計 O(n²) になります。
一方、push は先頭に cons セルを 1 つ作るだけで、最後の nreverse に O(n)。

これを計測するために、繰り返しのベンチマーク関数を用意しました。

(defun bench-naive (n repeat)
  (dotimes (k repeat) (build-list-naive n)))

(defun bench-fast (n repeat)
  (dotimes (k repeat) (build-list-fast n)))

(time (bench-naive 3000 200))
(time (bench-fast 3000 200))Code language: Lisp (lisp)

2.1. 計算量の差を実測で確認する

実行すると、たとえばこのような差が出ます。

* (time (bench-naive 3000 200))
Evaluation took:
  5.621 seconds of real time
  5.203932 seconds of total run time (4.971306 user, 0.232626 system)
  [ Real times consist of 0.619 seconds GC time, and 5.002 seconds non-GC time. ]
  [ Run times consist of 0.577 seconds GC time, and 4.627 seconds non-GC time. ]
  92.58% CPU
  9,039,625,047 processor cycles
  3 page faults
  14,404,781,104 bytes consed

;; bench-fast
* (time (bench-fast 3000 200))
Evaluation took:
  0.006 seconds of real time
  0.005807 seconds of total run time (0.005718 user, 0.000089 system)
  100.00% CPU
  9,924,337 processor cycles
  9,596,336 bytes consedCode language: Lisp (lisp)
2.1. 計算量の差を実測で確認する

速い方は0.006秒なのに対して遅い方は、5.6秒もかかっています。
また、時間だけでなくメモリ確保量（bytes consed）も、9MBと14GBと大きな差がありますね。

アルゴリズムの計算量が本当に違うかを確認するには、n を段階的に増やして time で比較するのが分かりやすいです。

(time (build-list-naive 1000))
(time (build-list-naive 2000))
(time (build-list-naive 4000))Code language: Lisp (lisp)

GC のタイミングや処理系の最適化で多少ぶれますが、O(n²) は n を 2 倍にすると時間が約 4 倍になるという傾向が出てきます。

3. sb-sprof で重い関数を特定する

さて、build-list-naiveのどの部分が足を引っ張っているか確認するのが、統計的プロファイラです。

sb-sprof — 重い関数を特定する 仕組み 0.01秒ごとにサンプリング APPEND2 naive APPEND2 naive 多く引っかかる = 時間を使っている (require :sb-sprof) (sb-sprof:with-profiling …) flatレポート出力例 Nr Self% Total% Function 1 70.4% 74.8% APPEND2 ← 2 21.7% 21.7% pthread… 3 3.1% 3.1% psynch… 8 0.2% 96.1% BUILD-LIST-NAIVE Self% が高い = そこが重い APPEND2 が 70% を占める :mode :alloc でメモリも調査可能

sb-sprof は、一定間隔（デフォルトで約 0.01 秒）でその瞬間のコールスタックをサンプリングして、どの関数が何回サンプルに引っかかったかを集計します1。
これによりサンプルが多い関数ほど、そこで時間を使っていると推定できるわけです。

ちなみに、SBCL にはもう一つ sb-profile というプロファイラもあります。こちらは対象関数に計測コードを差し込む方式で、呼び出し回数を正確に数えられます2。

sb-sprof は contrib（同梱の追加モジュール）なので、最初に require で読み込みます。

(require :sb-sprof)Code language: Lisp (lisp)

次に、計測したい処理を with-profiling で囲みます3。

(sb-sprof:with-profiling (:max-samples 3000 :report :flat)
  (bench-naive 3000 200))Code language: Lisp (lisp)

出力はこのような形になります。

Number of samples:   456
Sample interval:     0.01 seconds
Total sampling time: 4.56 seconds
Graph cycles:        0

           Self        Total        Cumul
  Nr  Count     %  Count     %  Count     %    Calls  Function
------------------------------------------------------------------------
   1    321  70.4    341  74.8    321  70.4        -  SB-IMPL::APPEND2
   2     99  21.7     99  21.7    420  92.1        -  foreign function __pthread_sigmask
   3     14   3.1     14   3.1    434  95.2        -  foreign function __psynch_cvwait
   4     11   2.4     11   2.4    445  97.6        -  FPR-SAVE
   5      3   0.7      3   0.7    448  98.2        -  foreign function gc_close_region
   6      2   0.4      7   1.5    450  98.7        -  foreign function lisp_alloc
   7      2   0.4      2   0.4    452  99.1        -  foreign function tlv_get_addr
   8      1   0.2    438  96.1    453  99.3        -  BUILD-LIST-NAIVE
   9      1   0.2      1   0.2    454  99.6        -  foreign function semaphore_wait_trap
  10      1   0.2      1   0.2    455  99.8        -  foreign function gc_alloc_new_region
  11      1   0.2      1   0.2    456 100.0        -  foreign function pthread_mutex_lock
...Code language: CSS (css)
3. sb-sprof で重い関数を特定する

APPEND が全体の 70.4 %と大きく、末尾追加のたびにリスト全体をコピーしているのが、処理時間の大部分を占めているとわかります。

3.1. flatレポートの読み方

flat レポートの主な列は次の通りです。

列意味
Self Count / %その関数自身でサンプルされた回数と割合
Total Count / %その関数の呼び出し先も含めた割合
Function関数名

最初は Self % が高い関数に注目するだけで十分です。
そこが実際に時間を使っている場所です。
Total % が高くても Self % が低い場合は、呼び出し先のどこかが重いので、呼び出し先を見に行きます。

サンプリングベースなので結果は多少ぶれます。
気になる場合は同じ計測を複数回行って、傾向が一致するか確認してみてください4。

3.2. Number of samples: 0

ちなみに、sb-sprof でよくある失敗が、Number of samples: 0 という結果です。

というのも、関数 1 回の実行が 0.01 秒より短いと、サンプリングのタイミングに全く引っかからないからです5。

測りたい処理を何万回も繰り返す「ベンチ関数」を用意して、数秒程度は走らせてください。

3.3. with-profilingのオプション

主なオプションは次の通りです。

  • :max-samples — 取得するサンプルの最大数。
    多いほど精度が上がりますが、長く走らせる必要があります。
  • :report — 結果の表示形式。
    :flat は関数ごとの集計、:graph は呼び出し木を出します。
    最初は :flat で十分です。
  • :mode — デフォルトは :cpu（CPU 時間でサンプリング）。
    :alloc にするとメモリ確保の多い場所を調べられます6。

メモリ確保が多い場合は :mode :alloc でアロケーションプロファイルを取ると、どこで大量に cons しているかも分かります。

(sb-sprof:with-profiling (:max-samples 3000 :report :flat :mode :alloc)
  (bench-naive 3000 200))Code language: Lisp (lisp)
  1. デフォルトのサンプリング間隔は *sample-interval* 変数で制御されており、初期値は 0.01 秒です。with-profiling の :sample-interval キーワードで変更できます。 – SBCL ソースコード sb-sprof/interface.lisp
  2. SBCL の公式マニュアルでは sb-profile を “exact per-function profiler”、sb-sprof を “statistical profiler” と区別して案内しています。 – SBCL User Manual
  3. マルチスレッド環境では、with-profiling を実行したスレッドのみがデフォルトでプロファイリングされます。複数スレッドを同時に計測したい場合は sb-sprof:start-profiling に :threads :all を渡す方法もあります。 – SBCL User Manual – Statistical Profiler
  4. sb-sprof は元々 Gerd Moellmann が CMUCL 向けに開発した統計的プロファイラを SBCL に移植・拡張したものです。cl-flamegraph など、sb-sprof の結果をフレームグラフ形式で可視化するラッパーライブラリも公開されています。 – Common Lisp Cookbook – Performance
  5. サンプルが取れなかった場合、SBCL は “No sampling progress; run too short, sampling interval too long, inappropriate set of sampled thread, or possibly a profiler bug.” という警告を出力します。サンプリング間隔を短くするか、計測対象を長く走らせることで解消できます。 – SBCL devel mailing list
  6. :mode :alloc は世代別 GC（generational garbage collector）を使用する SBCL ビルドでのみサポートされています。また、2レベルを超える呼び出しスタックの追跡は x86 および x86-64 でのみ対応しています。 – SBCL User Manual – Statistical Profiler