チューニング失敗ケース

2ヶ月くらい間を空けて、同じ失敗をしたので記録としてここに残す。
今の Mosh のプロファイラは強力で、遅い手続きの特定は簡単にできる。
これのおかげでチューニングはかなり楽になっているのだが、まだ人力でがんばらないといけない部分がある。
それは手続きのどの部分が遅いのか？という特定しなければいけないこと。

通常であれば手続きは短くコンパクトなので、すぐに特定できる。だがコンパイラ中の大きな case 文などがある場合には少し難しい。
行き当たりばったりで遅いところを探すのは論外なので、case の各 clause の処理の前後に (get-timeofday) をはさみログを取ることにした。

(case val
  [(hoge) (print 'hoge (get-timeofday)) 重い処理 (print (get-timeofday))]
...
)

のようなイメージ。ログを出力しておいて後でログの解析をして遅い case を特定すればよい。
このようなことを実現したかったらマクロでやるのが元のコードをあまり汚さずうれしい。

(define-macro (case-with-time val . clauses)
  `(case ,val
     ,@(map (lambda (clause)
             (match clause
               [(p . more)
                (let1 temp (gensym)
                `(,p (let1 ,temp (get-timeofday) (let1 v (begin ,@more) (display "(log ") (display (quote ,p)) (display ,temp) (display (get-timeofday)) (display ")\n") v))))]))
           clauses)))

case を case-with-time に置き換えれば、ログを吐くようになる。ついでにログにはどの case 条件かも吐かれるようになっている。(quote ,p) のところ。

さあこれで完璧だ。一気に遅いところが分かるぜ。と思ったらどうも数字がおかしい。プロファイラで計測したときよりも明らかに数字が大きい。

鋭い方ならこの方法がうまく機能しない場合を簡単に思いつくのかもしれない。
さてあなたは分かったでしょうか。（僕は気づきませんでした）
正解は「手続きが再帰している場合には実行時間が累積してしまうこと」です。
hoge 手続きの case a を通る -> hoge が再帰している -> hoge 手続きの case b を通る。
のような流れの場合、case a の実行時間に case b の実行時間が足されてしまいます。

特に Scheme 場合は上のような例がたくさんあるので注意が必要ですね。２回も同じミスをしてしまった自分が悲しいです。

じゃあどういう方法を取ったら良いのかといわれると困るのですが Mosh の場合はプロファイラが無名 lambda の実行をカウントしてくれることを利用して重い処理を lambda でくるんであげれば良い。

(case val
  [(hoge) ((lambda () 重い処理))]
...
)