ClojureハッカソンであるTokyo.clj#15に行って来ました。
そこで前々から気になっていたClojureでの性能測定（プロファイリング）の方法について試してみたのでまとめます。
性能測定といってもいろいろな切り口があるので、今回は「実行速度」と「メモリ使用量」に限定して調べて見ました。
その結果、次の3つが手軽でいいかなーと思ったので説明します。
1,2はClojure用の性能測定ツール、3のVisualVMはJava用のJVMモニタリングツールです。それぞれ一長一短があるので、まずは使い方から説明していきます。
【clojure.core/time】
S式の実行速度を表示する関数です。
『プログラミングClojure』でもよく使われているから知っている人は多いでしょう。
測定用のサンプルとして竹内関数を実装して計測して見ました。
; たらい回し関数（竹内関数）
(defn tarai [x y z]
(if (<= x y)
y
(tarai
(tarai (dec x) y z)
(tarai (dec y) z x)
(tarai (dec z) x y))))
user> (time (tarai 19 16 11))
"Elapsed time: 13.304 msecs"
19REPL上でいちばん手軽に性能測定ができる方法ですね。
【clojure.contrib.profile】
拡張ライブラリにあるプロファイラ用ライブラリです。
timeだと全体の実行時間しか分からなかったんですが、これを使うと測定したい部分をもっと細かく指定できます。
まずコードの中で測定したい部分をprofでキーワードとともに包んでやります。
そのあとtimeと同じようにprofileから呼び出してやると、指定部分ごとに実行時間の平均／最短／最大と実行回数をまとめた表を見せてくれます。
(defn prof-tarai [x y z]
(if (<= x y)
y
(prof-tarai
(prof :arg-x (prof-tarai (dec x) y z))
(prof :arg-y (prof-tarai (dec y) z x))
(prof :arg-z (prof-tarai (dec z) x y)))))
user> (profile (prof-tarai 10 5 2))
Name mean min max count sum
arg-x 117410 0 2127000 100 11741000
arg-y 70040 0 2960000 100 7004000
arg-z 64230 0 1668000 100 6423000
nil
時間の単位はナノ秒です。
以下のように*enable-profiling*にfalseを指定してやると、コンパイル時にプロファイル用コードを除去してくれるそうです。
user> (binding [clojure.contrib.profile/*enable-profiling* false]
(macroexpand '(prof :abc (+ 2 3))))
(do (+ 2 3))
以下ちょっと不満点
timeと違って実行結果は返してくれません。結果表をプリントするだけで常にnilを返します。
さらに計測で使ってるSystem.nanoTime()はlong型を返しますが、数分かかるような重い処理だと途中で桁あふれを起こして止まる場合があります（Integerでキャストしている部分が怪しい）。
ナノ秒で測っていることから考えて測定精度を優先して作られているのかなーと思いました。
Clojureメーリングリストを調べてみたら作者のStuart Sierraさんが「half-bakedなんで本気でやるならJVMプロファイラ使ってね」と言ってました。
ここらへん改良したのを作りたいなー。
【VisualVM】
上2つはClojure純正ツールでしたが、こっちはJava用のツールをClojureに応用してみたというものです。
JVMをモニタリングしてメソッド単位で実行速度・メモリ使用量などを計測してくれます。
そのほかにもいろいろ機能があるみたいなので細かいことを公式サイト参照すべし（日本語ドキュメントあり）。
VisualVM 入門 — Java.net
VisualVMを起動してClojureのREPLを立ち上げると、左側のツリービューにREPLの動いているVMが表示されます。それをダブルクリックするとこんな画面が開きます。
ここではCPU使用率とかヒープメモリ使用量のグラフを表示してくれます。このままでも十分有益なデータが得られますね。
プロファイル情報を得たいときは、［プロファイラ］のタブで画面を切り替えます。
［CPU］と［メモリー］のどっちかのボタンを押してから測定したいコードを実行すると、Javaのメソッド単位で処理速度やメモリ使用量を測ってくれます。
Clojureで定義した関数なんかはこんなふうにリストに出てきます。あくまでJava用ツールなのでClojure視点だと結果が読みにくいんですが、下にあるテキストボックスで絞込みが出来るので、それを上手く使うともうちょっと読みやすくなります。
【まとめ】
time、c.c.profileはREPL上で使うのに都合がいいです。ただし実行速度計測がメインで、メモリ使用量なんかは分かりません。チューニングが必要なときに「コード修正して計測」というループを素早く繰り返したいときには楽ですね。
VisualVMは高機能で網羅的ですが、開発中に何度も繰り返し使うというには重い。「ある程度完成しているアプリで何かボトルネックがある、その箇所にあたりを付ける」という場合に使うと良いと思います。
全体的にはClojureの性能測定ツールはまだ発展途上、という感想です。
【参考リンク】
Fatvat: JVisualVM and Clojure
Tokyo.clj#15 - Togetter
Tokyo.clj二次会ではClojure以外の言語の話題でもよく盛り上がって面白いです。
