Emacsのプロファイリング機能の紹介

序

昔から重いと悪評高いEmacsならではなのか、(遅くともバージョン18から)Emacsにはプロファイリング機能が同梱されていたようです。このプロファイリング機能に関してはelispマニュアルにはメインとなるprofiler.elの他にもelp.elやbenchimark.el、trace.elにも言及されています。が、バージョン25から26になって記載も若干充実したものの「詳細はソースを参照されたし」な所は変わりありません。なのでソースのコメントを翻訳などして紹介します。

本文

まずはマニュアル

debugging.texi

18. Lispプログラムのデバッグ

... 中略 ...

• trace.elパッケージが提供するトレース機能を使用して問題に
関する関数の実行をトレースできます。
このパッケージは関数呼び出しのトレース用に
trace-function-foregroundとtrace-function-background、
値をトレースする変数の追加用にtrace-valuesという関数を提供
します。詳細はtrace.elにあるこれらの機能のドキュメントを参照
してください。

... 中略 ...

18.5. プロファイリング

プログラムは正常に機能しているものの、十分に高速ではないので
より高速かつ効率的に実行させたい場合にまず行うべきは、そのプ
ログラムが実行時間の大半をどこで消費しているか知るために、
コードをプロファイル(profile)することです。ある特定の関数の実
行が、実行時間のうちの無視できない割り合いを占めるようなら、
その部分を最適化する方法を探すことを開始できます。 

Emacsには、このためのビルトインサポートがあります。プロファイ
リングを開始するには、`M-x profiler-start`をタイプします。
プロファイルはプロセッサー使用(processor usage)、メモリー使用
(memory usage)、またはその両方を選択できます。それから高速化
したいコードを実行します。その後に`M-x profiler-report`と
タイプすると、プロファイルに選択した各リソース(CPUとメモリー)が
`summary`バッファーに表示されます。reportバッファーの名前には、
そのレポートが生成された時刻が含まれるので、前の結果を消去せ
ずに後で他のレポートを生成できます。プロファイリングが終了し
たら、`M-x profiler-stop`とタイプしてください(プロファイリング
に関連したオーバーヘッドが若干あるので実際に調査したいコード
の実行中以外はアクティブのまま放置するのは推奨しない)。 

profiler reportバッファーでは、各行に呼び出された関数と、その
後にプロファイリングが開始されてから使用したリソース(CPUまた
はメモリー)の絶対時間とパーセンテージが表示されます。左側にシ
ンボル`+`のある行では`RET`をタイプして行を展開して、高位レベ
ルの関数に呼び出された関数を確認できます。関数ツリー配下全体
の呼び出しを確認するにはプレフィクス引数を使用します(`C-u
RET`)。もう一度`RET`をタイプすると、元の状態へと行が折り畳まれま
す。 

`j`または`mouse-2`を押下すると、ポイント位置の関数の定義にジャン
プします。`d`を押下すると、関数のドキュメントを閲覧できます。
`C-x C-w`を使用して、プロファイルをファイルに保存できます。`=`を
使用すれば、2つのプロファイルを比較することができます。 

elpライブラリーは、プロファイルしたいLisp関数が事前に解ってい
るときに有用となる別のアプローチを選択肢として提供します。こ
のライブラリーの使用するには、まず`elp-function-list`に関数シン
ボルのリスト(プロファイルしたい関数)をセットします。それから
関数をプロファイル用にアレンジするために、`M-x
elp-instrument-list RET nil RET`とタイプします。プロファイルし
たいコードの実行後に、`M-x elp-results`を呼び出してカレント結果
を表示します。処理手順の詳細については`elp.el`ファイルを参照し
てください。このアプローチはLispで記述された関数のプロファイ
リングに限定されており、Emacsプリミティブのプロファイルはでき
ません。 

benchmarkライブラリーを使用して、個別のEmacs Lispフォームの評
価に消費される時間を計測できます。`benchmark.el`内のマクロ
`benchmark-run`と`benchmark-run-compiled`を参照してください。
フォームをインタラクティブに時間計測するために`benchmark`コマン
ドも使用できます。 

configureのオプションに`--enable-profiling`を使用してビルドする
ことにより、EmacsをCコードのレベルでプロファイルすることがで
きます。こうしてビルドされたEmacsは、Emacsをexitするときに
`gprof`ユーティリティを使用して検証できるファイル`gmon.out`を生成
します。この機能は主にEmacsのデバッグに有用です。このEmacsは
実行状態から上述の`M-x profiler-…`コマンドによりLispレベルで実
際にストップします。 

---
Extracted from elisp manual of Emacs-26.3,
 and then translated to Japanese by ayatakesi.
This article is licensed under original documents' license (I mean GFDLv3).

profiler.el

メインのプロファイリング機能としてマニュアルに詳細に記述されているんで割愛します。

trace.el

trace.elのコメントの日本語訳

翻訳にあたってEmacsWikiとか参照したんですが、ドキュメントにはM-x find-library RET trace RETの1行しか記載なしという潔さなのでソースのコメントしか手掛かりなしです。

trace.el

# trace - tracing facility for Emacs Lisp functions

*Author:* Hans Chalupsky <[e-mail]><br>

イントロダクション:
=============
`nadvice.el`を利用するシンプルなトレース用のパッケージです。
これはLisp様式の情報を生成して、それをトレース出力バッファーに
挿入します。トレース出力の生成があなたの行っていることと干渉する
ことがないように、トレースはバックグラウンド(もしくは暗黙裏)で
行うことができます。

制限:
=============
- トレースされるサブルーチン(訳注: subrpがtをリターンする
- ビルトイン関数)がインタラクティブに呼び出された際は常にそれら
  の引数の値としてnilを表示するだろう
- 関数セルを介して呼び出される関数、マクロ、サブルーチンだけが
  トレース出力を生成し、以下にたいするトレース出力は入手できない:
  + 他のサブルーチンやCコードから直接呼び出されるサブルーチン
    (carやcdrなど)関連付けられた特別なバイトコードをもつサブ
  + ルーチンにたいするコンパイル済みの呼び出し
    コンパイルの間に展開されるマクロ
- nadvice.elに適用されるすべての制限

使用法:
======
- 関数をトレースするには<kbd>M-x trace-function</kbd>を
  実行します。これはトレースする関数、サブルーチン、マクロの名前
  を尋ねます。
- バッファーを切り替えたり、その他のディスプレー指向の何かを行う
  関数をトレースしたいなら<kbd>M-x trace-function-background</kbd>
  を使用してください。これはウィンドウのポップアップやその他の
  煩しい何かを行うことなく、バックグラウンドで暗黙裏にトレース
  出力を生成します。
- 関数のトレースを中止するには<kbd>M-x untrace-function</kbd>
  を実行してください。
- カレントでトレース中のすべての関数のトレースを中止するには
  <kbd>M-x untrace-all</kbd>を実行してください。

例:
=========

     (defun fact (n)
       (if (= n 0) 1
         (* n (fact (1- n)))))
     fact

     (trace-function 'fact)
     fact

 これを評価すると...

     (fact 4)
     24

... *trace-buffer*に以下が生成されるでしょう

 1 -> fact: n=4
 | 2 -> fact: n=3
 | | 3 -> fact: n=2
 | | | 4 -> fact: n=1
 | | | | 5 -> fact: n=0
 | | | | 5 <- fact: 1
 | | | 4 <- fact: 1
 | | 3 <- fact: 2
 | 2 <- fact: 6
 1 <- fact: 24

     (defun ack (x y z)
       (if (= x 0)
           (+ y z)
         (if (and (<= x 2) (= z 0))
             (1- x)
           (if (and (> x 2) (= z 0))
               y
             (ack (1- x) y (ack x y (1- z)))))))
     ack

     (trace-function 'ack)
     ack

 以下を試すと面白いトレースが出力されます:

     (ack 3 3 1)
     27

以下はあまりに高速なために見逃すかもしれないメッセージを調べる
機会を与えるためのRobert Potterのパッケージl`log-message.el`
と幾分類似する処理を行います(サブルーチンが生成するメッセージを
目にすることはないかもしれない):

    (trace-function-background 'message "*Message Log*")

変更履歴:

Revision 2.0 1993/05/18 00:41:16 hans
    * Adapted for advice.el 2.0; it now also works
      for GNU Emacs-19 and Lemacs
    * Separate function `trace-function-background`
    * Separate pieces of advice for foreground and background tracing
    * Less insane handling of interactive trace buffer specification
    * String arguments and values are now printed properly

Revision 1.1 1992/12/15 22:45:15 hans
    * Created, first public release


---
Converted from `trace.el.gz` by [*el2markdown*](https://github.com/Lindydancer/el2markdown).
and then translated to Japanese by ayatakesi.
This article is licensed under same-level license of trace.el (included in Emacs distribution) for documentation (I mean GFDLv3).

補足

解りやすい使用例がコメントに記載されているんですね。マニュアルでは言及されているもののコメントに例が記載されていないtrace-valuesはptintfデバッグみたいなことを行うための関数のようです。使用例を探しましたがemacs-develの解答例があったので実行してみました。

ちなみにtrace.elの記載がマニュアルに追加されたのはEmacs-26(Emacs-26.1は2018/05/28リリース)からですが、MLの回答日付が2018/05/26(！？ (；ﾟДﾟ))))

elp.el

elp.elのコメントの日本語訳

elp.el

# elp - Emacs Lisp Profiler

*Author:* Barry A. Warsaw<br>

複数の関数をプロファイルしたければelp-function-listにシンボル
のリストをセットしてM-x elp-instrument-listを行ってください。
これはこれらの関数が呼び出される度にプロファイリング情報が記録さ
れるように関数をハッキングします。カレント結果をプリントするには
M-x elp-resultsを使用します。別バッファーではなく標準出力に出
力したければelp-use-standard-outputを非nilにsetqしてくださ
い。elp-reset-after-resultsに非nilをセットすると結果が表示さ
れる度にプロファイリング情報がリセットされます。
M-x elp-reset-allで任意のタイミングですべてのプロファイリング
情報をリセットすることもできます。


パッケージがGNUコーディング規約の一般的なテキストプレフィクスに
したがっていれば、任意のパッケージ内のすべての関数のインストルメ
ントもできます。これを行うにはelp-instrument-packageを使用し
てください。

結果をソートしたければelp-sort-by-functionに何らかの述語関数
をセットしてください。もっとも一般的と思われる以下の3つの選択肢が
事前定義されています:
    elp-sort-by-call-count
    elp-sort-by-average-time
    elp-sort-by-total-time

elp-report-limitをセットすることで、与えられた回数より呼び出し
回数が少ないすべての関数を出力から除外することもできます。

elpはインタープリターで解釈される関数と同様にバイトコンパイル済み
関数もインストルメントできますが、マクロのインストルメントはでき
ません。しかし(たとえばeval-defunで)関数を再定義したときには、
M-x elp-instrument-functionで再インストルメントが必要になる
でしょう。これによりその関数のプロファイリング情報もリセットされま
す。elpはインタラクティブな関数(つまりコマンド)も処理できますが、
ユーザーの入力の待機に費やされる時間は、timeに関する結果に当然反
映されるでしょう。

`マスター`関数の指定も可能です。インストルメントされた関数の時間
プロファイリングは、このマスター関数の実行の間でのみ集積されます。
つまり以下のようなdefunがあるとしましょう:

     (defun foo () (do-something-time-intensive))
     (defun bar () (foo))
     (defun baz () (bar) (foo))

そしてbarの実行中だけ barとfooで消費される時間を知りたいならbar
をマスターにします。bazからのfoo呼び出しはfooの時間総計には追加さ
れなくなります。この機能を利用するにはM-x elp-set-masterと
M-x elp-unset-masterを使用します。
一度に1つのマスター関数だけがセットできます。

elp-restore-functionで任意の関数のオリジナルの定義をリストアで
きます。elp-restore-functionで任意の関数のオリジナルの定義を
リストアできます。

以下はelpのカスタマイズに使用できる変数のリストです:

  elp-function-list
  elp-reset-after-results
  elp-sort-by-function
  elp-report-limit

以下はインタラクティブに使用可能なコマンドのリストです:

  elp-instrument-function
  elp-restore-function
  elp-instrument-list
  elp-restore-list
  elp-instrument-package
  elp-restore-all
  elp-reset-function
  elp-reset-list
  elp-reset-all
  elp-set-master
  elp-unset-master
  elp-results

報告される時間が不正確になる数多な要因が存在することに注意してくだ
さい。これらの要因にはシステムクロックの精度と粒度、およびlispの
計算やインターバルの記録に費されるオーバーヘッドが含まれます。後者
に関してはほぼ一定だと把握できるので、これらの関数はプロファイ
リング中の種々のlispルーチンに費される処理量に関して良いフィーリ
ングを与えることができると私は考えています。時間は実時間を使用して
計算されているので、他のシステム負荷も精度に影響し得ることにも注意
してください。

バックグラウンド:

このプログラムはBoaz Ben-Zviによるprofile.elとRoot Boy Jim
によるprofiler.elという、私が把握する2つの既存のEmacs Lisp
プロファイラーからのみインスパイアされたものです。両者はEmacs-18
用に記述されており、両者共にプロファイリングにおいて非常に良好な
初見を与えるものですが、私が望む機能とインターフェースが提供されて
いないことに気づいたので、このプログラムを記述しました。elpは
XEmacs-19とEmacs-19でテストしました。Emacs-18でテストを
試みても意味はないでしょう。

以前のプロファイラーと異なり、インターバル時間をリターンするため
に、elpはEmacs-19のビルトイン関数を使用しています。これにより
外部Cプログラムとそのようなプログラムと対話するEmacsプロセスの
両者が不要になり、結果としてパッケージ全体が簡素化されました。

未定:

これが実際のプロファイラーのように、実行の全ブランチで消費される
時間が記録されるようにする。

---
Converted from `elp.el` by [*el2markdown*](https://github.com/Lindydancer/el2markdown).
and then translated to Japanese by ayatakesi.
This article is licensed under same-level license of elp.el (included in Emacs distribution) for documentation (I mean GFDLv3).

感想

Emacs-19から同梱されている最古?のプロファイラーで作者のBarry A. Warsawさんは現在python界隈で有名な人らしいです。マクロとプリミティブは対象外ですがGNUコーディング規約に準拠したパッケージ(つまりEmacs同梱の全パッケージ、もしかするとelpaのほとんどのパッケージ)であればパッケージの全関数のプロファイリングが一発で可能な模様。試しにとても重いページをewwで表示してみたら以下のようになりました:

benchmark.el

benchmark.elのコメントの日本語訳

benchmark.el

# benchmark - support for benchmarking code

*Author:* Dave Love  <[e-mail]><br>

GC(ガーベージコレクション)に消費される時間を含むフォーム実行時間
用のユーティリティーです。コードの時間計測に先立ち、GC実行直後で
あること、関連するコードがロード済みであること(なのでautoload等
によるオーバーヘッドがない)、それが適切ならコードがコンパイル済み
であること(ですが`benchmark-run-compiled`を参照してください)
のような事項を確実にしておきたいと思うでしょう。

(defmacro benchmark-elapse (&rest forms)
  "FORMS実行に経過した秒数をリターンする。"

(defmacro benchmark-run (&optional repetitions &rest forms)
  "FORMSの実行時間。
数値としてREPETITIONSが与えられた場合は、ループによるオーバー
ヘッドを考慮しつつフォームをその回数実行する。それ以外ならFORMS
を1回実行する。実行の総経過時間、GCの実行回数、GCに消費された
時間のリストをリターンする。
`benchmark-run-compiled`も参照のこと。"

(defmacro benchmark-run-compiled (&optional repetitions &rest forms)
  "FORMSのコンパイル済みバージョンの実行時間。
`benchmark-run`と同様だが`lambda`でFORMSをラップすることに
より取得されるバイトコードのfuncallの時間である。`lambda`によ
るオーバーヘッドは考慮済み。"

(defun benchmark (repetitions form)
  "FORMをREPETITIONS回実行した際の経過時間をプリントする。
インタラクティブに呼び出した場合、REPETITIONSはプレフィクス
引数から取得するとともに、このコマンドはベンチマークするフォーム
の入力を求める。非インタラクティブな使用については
`benchmark-run`と`benchmark-run-compiled`も参照されたい。"

---
Converted from `benchmark.el` by [*el2markdown*](https://github.com/Lindydancer/el2markdown).
and then translated to Japanese by ayatakesi.
This article is licensed under same-level license of benchmark.el (included in Emacs distribution) for documentation (I mean GFDLv3).

お試し

思い付かなかったのでEmacsWikiのバブルソートの例をそのままやってみました。

*scratch*

;; This buffer is for text that is not saved, and for Lisp evaluation.
;; To create a file, visit it with <open> and enter text in its buffer.

(benchmark-run 100
  (let* ((list (mapcar 'random (make-list 100 most-positive-fixnum)))
     (i (length list)))
    (while (> i 1)
      (let ((b list))
    (while (cdr b)
      (when (< (cadr b) (car b))
        (setcar b (prog1 (cadr b)
            (setcdr b (cons (car b) (cddr b))))))
      (setq b (cdr b))))
      (setq i (1- i)))
    list))

==> (1.707226042 0 0.0)


 (benchmark-run-compiled 100
      (let* ((list (mapcar 'random (make-list 100 most-positive-fixnum)))
              (i (length list)))
         (while (> i 1)
           (let ((b list))
             (while (cdr b)
               (when (< (cadr b) (car b))
                 (setcar b (prog1 (cadr b)
                             (setcdr b (cons (car b) (cddr b))))))
               (setq b (cdr b))))
           (setq i (1- i)))
         list))

==> (0.458427083 1 0.22598020899999938)

コンパイルしたほうが速いですねえ。

他の例も試してみましょう。

emacs-develでは丁度この記事を書いてる時点(2019-11-30)でStarting the Emacs 27 release cycleというwktkなスレが始まっています。そのemacs-27からjanssonがインストールされていればjsonがデフォルトでサポートされるようです。前記スレの数日前にこれに絡んでSpeedup of functions to en/decode UTF-8 textという性能改善がコミットされました。丁度良いので当該コミットのビフォーアフターをbenchmarkしてみました。

まず改善の1つ前のコミットでベンチマークをとります(改善対象のcoding.cのテスト用にtest/src/coding-tests.elというのがあるんですが、改善によりdecode_string_utf_8の引数が追加されたりで新バージョンでは動作しないので、改善された関数を呼び出す処理でベンチマークをとりました)。

6d4d00c63417e3479e978a373f252b9f2709ce39

$ git clone https://git.savannah.gnu.org/git/emacs.git
    ...
$ cd emacs
$ git checkout 6d4d00c63417e3479e978a373f252b9f2709ce39
$ ./autogen.sh
    ...
$ ./configure
    ...
$ make
    ...
$ cd src
$ ./emacs --batch \
         --visit ~/elisp-ja.json \
         --eval '(pp (benchmark-run-compiled 100 (json-parse-string (buffer-string))))'
(92.810553213 200 12.846304656)
$ ./emacs --batch \
         --visit ~/elisp-ja.json \ 
         --eval '(pp (benchmark-run-compiled 100 (progn (goto-char (point-min)) (json-parse-buffer)))))'
(78.081415458 100 7.242530514)

次に改善のあったコミットでベンチマークをとってみます。

c26556bd18f8ca1e891bd1750c9f95b21ea457b0

$ git checkoout c26556bd18f8ca1e891bd1750c9f95b21ea457b0
    ...
$ make
    ...
$ cd src
$ ./emacs --batch \
          --visit ~/elisp-ja.json \
          --eval '(pp (benchmark-run-compiled 100 (json-parse-string (buffer-string))))'
(80.903451352 200 12.851802737)
$ ./emacs --batch \
         --visit ~/elisp-ja.json \
         --eval '(pp (benchmark-run-compiled 100 (progn (goto-char (point-min)) (json-parse-buffer)))))'
(76.942927503 100 8.812791023)

速くなってます。

結び

個人的にはelpパッケージがかなり便利に感じました。

余談

Emacsの性能改善に絡み、Advent Calendar in 2019開幕直前の2019-11-30時点でemacs-develとredditにelispをgccでネイティブコンパイルしちゃうという凄そうなのが紹介されました。コンパイルしたelispのデバッグがどうなるか？等もありますが、MLでの反響も概ね良好でこのまま行けばElpaにも取り込まれるかも。楽しみ〜