Lispでtimeit! - Hyでコード実行時間を測定する

これは[iRidge Advent Calendar](http://qiita.com/advent-calendar/2016/iridge)の八日目の記事です。

この記事では、Pythonで実装されたLisp方言Hyでコード実行時間を測定する方法を考えます。

# 動機

株式会社アイリッジのCommon Lisp大好きサーバサイドエンジニア、tanaka.lispです。昨日に続けての投稿となります。

[昨日の記事では、Pythonで書かれた夢の言語Hyを紹介しました](http://qiita.com/tanaka-lisp/items/07ac1c7e413b43f8b6a8)。

そのなかで、コード片の実行時間を計測したいなあと思いました。アナフォリックマクロの説明に用いた重そうな`reduce`呼び出しのところです。記事では

> この式、とりあえず打ってみたら一分くらいREPLが沈黙してしまいました:sob:。

と書きましたが、実際処理にどれだけの時間が掛かったのか、気になって気になって夜も眠れません。こんなときCommon Lispだったら`time`関数に式を与えると、実行時間合計に加え、システム時間、ユーザ時間、それに処理系依存ではありますが、メモリ使用量(SBCL)などなどを教えてくれます。素敵。Common Lispとてもステキ。

```lisp
CL-USER> (time (reduce #'+ (loop :for i :from 0 :upto 1000000 :collect i)))
Evaluation took:
  0.051 seconds of real time
  0.048867 seconds of total run time (0.040434 user, 0.008433 system)
  [ Run times consist of 0.032 seconds GC time, and 0.017 seconds non-GC time. ]
  96.08% CPU
  136,523,685 processor cycles
  49 page faults
  15,983,024 bytes consed
```

今回は、同じようなことがHyでもできないかと思い、試行錯誤を重ねてみました。

# Pythonにおけるコード実行時間測定

まず、Pythonではこれをどのようにやればよいでしょうか。ググってみると**自分でシステム時間を取得して結果を得る**方法とともに、こんなPythonモジュールドキュメントが見つかります。

[27.5. timeit — 小さなコード断片の実行時間計測](http://docs.python.jp/2/library/timeit.html)

このように使うようです:

```python
>>> from timeit import timeit
>>> timeit('reduce(lambda a, b: a + b, range(1, 100000))', number=1)
0.015338897705078125
>>> timeit('reduce(lambda a, b: a + b, range(1, 10000000))', number=1)
1.8167369365692139
```

引数として**文字列で表現されたコード**を渡し、オプショナルなキーワード引数で実行回数を指定します。キーワード引数`number`のデフォルト値は`1000000`であり、いくらなんでもたくさん実行しすぎなため、ここでは1としました。

コードをわざわざ文字列で表現しなければならないところに幾許かのダサさを感じてしまいますが、PythonはLispのように同図像性(homoiconic)を持たないので、いたしかたない部分ではあります。

というわけで、[Lispでtimeit!](https://www.youtube.com/watch?v=Ym0hZG-zNOk) Hyでやってみましょう。

```clojure
=> (import [timeit [timeit]])
=> (timeit '(reduce + (range 1 10000000000)))
Traceback (most recent call last):
  File "<input>", line 1, in <module>
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/timeit.py", line 236, in timeit
    return Timer(stmt, setup, timer).timeit(number)
  File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/timeit.py", line 155, in __init__
    raise ValueError("stmt is neither a string nor callable")
ValueError: stmt is neither a string nor callable
=>
```

おうふ！　怒られてしまいました。ですよねー。Pythonコードの文字列を受けとるんだから、S式でコード渡したら怒られるに決まっていますよねー。

そういうわけで、別の手を考えなければなりません。

# Hyではどうするか

Hyのコードで`timeit`関数を利用したい場合、どうしたらいいでしょうか。`timeit`がPythonコード片しか受理しないと言い張るのなら、いいでしょう、計測したいHyコードをPythonのコードになんとかがんばって変換して投げつけてやるしかありません。

この方法だと、Hyのコードをパースするオーバーヘッドが含まれないため、Hy言語上の実行時間測定としてどうなのという感が否めませんが……。ここはポジティブに考えることにして、純粋な計算時間を知ることができる喜びを分かちあおうではありませんか。

というわけで、実際どうやったものか、試行錯誤してみます。

## Hyコードを文字列に変換したい

### Hy構文木からPython ASTへの変換

まずはHyのコードをぼんやりと眺めてみます。

https://github.com/hylang/hy/tree/master/hy

Hyの実行モデルを全て追うようなことはしませんが、じーっとファイルを見ていくと…。うーむ。`hy/compiler.py`の`hy_compile()`あたりがあやしい。

```python
# https://github.com/hylang/hy/blob/master/hy/compiler.py#L2649
def hy_compile(tree, module_name, root=ast.Module, get_expr=False):
    """
    Compile a HyObject tree into a Python AST Module.

    If `get_expr` is True, return a tuple (module, last_expression), where
    `last_expression` is the.
    """
    ...
```

なんかASTとか書いてあるし、HyのコードオブジェクトをPythonの抽象構文木(Abstract Syntax Tree)に変換してそう。しかし、引数が文字列ではなさそうです。`tree`ってなんだろうなー。きっと字句解析の済んだ、Hyの抽象構文木なのかなー。

### 文字列からHy構文木への字句解析

字句解析部がほしい。そうすると`lex`モジュールが超字句解析してそうです。覗くと`lexer.py`や`parser.py`とかあって、大当たりっぽい。`hy/lex/__init__.py`を見ると、`tokenize()`がありました！

```python
# https://github.com/hylang/hy/blob/master/hy/lex/__init__.py
def tokenize(buf):
    """
    Tokenize a Lisp file or string buffer into internal Hy objects.
    """
    ...
```

字句解析はできそうなふいんき(ry)が満ちるのを感じます。いちどREPLで確認してみますと…

```clojure
=> (import hy)
=> (hy.lex.tokenize "(reduce (fn [a b] (+ a b)))")
[(u'reduce' (u'fn' [u'a' u'b'] (u'+' u'a' u'b')))]
=> (type (nth (hy.lex.tokenize "(reduce (fn [a b] (+ a b)))") 0))
<class 'hy.models.expression.HyExpression'>
```

ほうらきた！　ということは、これで`hy-compile`に投げられそうです。

```clojure
=> (hy.compiler.hy-compile (hy.lex.tokenize "(reduce (fn [a b] (+ a b)))") "hoge-module")
<_ast.Module object at 0x7fdab2cbc910>
```

やった！　でもなんだかよくわからないオブジェクトを突き返されました。ちなみに`"hoge-module"`というのは、`hy-compile`がモジュール名を必須引数とするためです。カレントモジュールを指定するためでしょうかね？

### Python ASTを文字列に変換

PythonのASTオブジェクトを手にしました。こんなものどうしろっていうのでしょう。ぼくは文字列に変換したいだけ…。そういえば`hy2py`なんてコマンドがありましたね、あれ、どうやってるんだろう…。

というわけで`hy/cmdline.py`の`hy2py_main()`を覗いてみましょう。

```clojure
# https://github.com/hylang/hy/blob/master/hy/cmdline.py#L415
# 
    ...
    if not options.without_python:
        if PY3 and platform.system() == "Windows":
            _print_for_windows(astor.codegen.to_source(_ast))
        else:
            print(astor.codegen.to_source(_ast))
    ...
```

[astor](https://github.com/berkerpeksag/astor)という、ASTを操作したりコードに変換したりするモジュールがあるのですね。いつ役立つかよくわからない学びがありました。

ということで、REPLで試してみます。

```clojure
=> (import hy astor)
=> (astor.codegen.to_source
     (hy.compiler.hy-compile (hy.lex.tokenize "(reduce (fn [a b] (+ a b)))")
     "hoge-module"))
'from hy.core.language import reduce\n\ndef _hy_anon_fn_1(a, b):\n    return (a + b)\nreduce(_hy_anon_fn_1)'
```

# そして蛇行し始める…

ところで、Hyコードを文字列に変換する手段がまだありません。ここからぼくは[`hydiomatic`モジュールの`-pprint`関数](https://github.com/hylang/hydiomatic/blob/master/hydiomatic/utils.hy)へと脱線しましたが、それは割愛します。**文字列に変換する必要はなかった!!**`hy-compile`関数のdocstringを落ち着いて読めばわかりました。

>     Compile a HyObject tree into a Python AST Module.

そして

> ```python
  => (type (nth (hy.lex.tokenize "(reduce (fn [a b] (+ a b)))") 0))
  <class 'hy.models.expression.HyExpression'>

なので、クオートしたコードをそのまま`hy-compile`に投げちゃっていいということです。

```clojure
=> (hy.compiler.hy-compile '(reduce (fn [a b] (+ a b))) "hoge-module")
Traceback (most recent call last):
...
HyCompileError: Internal Compiler Bug 😱
⤷ AttributeError: 'HySymbol' object has no attribute 'start_line'
...
```

怒られました:cry:。ただのHyObjectではなく、行番号も足してやらないといけないっぽいです。`hy/core/language.py`に[それっぽい関数がある](https://github.com/hylang/hy/blob/master/hy/core/language.hy#L174)のでこいつでラップして渡すと、

```clojure
=> (hy.compiler.hy-compile
     (hy.core.language.fake-source-positions '(reduce (fn [a b] (+ a b))))
     "hoge-module")
<_ast.Module object at 0x1058d9450>
```

おお、よさそう。じゃあこいつを`astor.codegen.to_source`につっこみます。

```clojure
=> (astor.codegen.to_source (hy.compiler.hy-compile (hy.core.language.fake-source-positions '(reduce (fn [a b] (+ a b)))) "hoge-module"))
''
```

空。**空文字列**。:angel:

ちなみに、[このモジュールの`-pprint`](https://github.com/hylang/hydiomatic/blob/master/hydiomatic/utils.hy#L29)を使って文字列化したものを`tokenize`、`hy-compile`したものはPythonコードが出力されることは確認済みです。無駄足。

方針変更です。

## 結局

`fake-source-positions`を探してるときに、HyコードをPython文字列に変換する関数が[標準で用意されている](http://docs.hylang.org/en/latest/language/core.html#disassemble)ことに気付きました。いままでの苦労がぜんぶ水泡に帰した気分でシアワセです。:smile:

```clojure
=> (disassemble '(reduce + (range 1 100000000)) :codegen True)
'from hy.core.shadow import +\nfrom hy.core.language import range, reduce\nreduce(+, range(1L, 100000000L))'
```

ともかく、これで実行時間計測コードは次のように書けるでしょう。

```clojure
=> (import [timeit [timeit]])
=> (timeit (disassemble '(reduce (fn [a b] (+ a b)) (range 1 10000000)) :codegen True) :number 1)
1.1246609687805176
```

ふう。:mask: 

あとはいつでもさくっと使えるよう、マクロとして定義すればおしまいです。

```clojure
=> (defmacro time [&rest body]
...   `(progn
...      (import [timeit [timeit]]
...              [hy [*]])
...      (timeit ~(disassemble body :codegen True) :number 1)))
=> (time (reduce (fn [a b] (+ a b)) (range 1 10000000)))
  File "<input>", line 1, column 1

  (time (reduce (fn [a b] (+ a b)) (range 1 10000000)))
  ^---------------------------------------------------^
HyMacroExpansionError: expanding `time': AttributeError("'tuple' object has no attribute 'start_line'",)
```

なんやねん、って感じですね。この`time`マクロはぜひ入ってほしいのと、この謎のエラーはバグっぽい感じがするので、趣味でプルリクを投げるといいのかもしれません。


# 別解2 

ところでこんな回りくどいことをやらなくても、実は簡単にHyコードを渡せちゃったりします。それは、Hyのコードを無名関数`fn`で包んでPythonのcallableオブジェクトとしてしまい、それを`timeit`関数に渡すというものです。

`timeit`モジュールの[イカ](https://github.com/hylang/hy/blob/master/docs/_static/cuddles-transparent.png)の箇所をぼけーっと眺めていて気付きました。

> stmt および setup パラメーターは、引数なしの呼び出し可能オブジェクトをとることもできます。呼び出し可能オブジェクトを指定すると、そのオブジェクトの呼び出しがタイマー関数に埋め込まれ、その関数が timeit() メソッドによって実行されます。この場合、関数呼び出しが増えるためにタイミングのオーバーヘッドが少し増える点に注意してください。
> --- http://docs.python.jp/3.5/library/timeit.html#timeit.Timer

はい。

> stmt および setup パラメーターは、引数なしの呼び出し可能オブジェクトをとることもできます。

大事なことなので二回書きました。

つまりこういうことです。

```clojure
=> (timeit (fn [] (reduce + (range 1 100000000))) :number 1)
424.17765402793884
```

悲しい。せっかくちょっとだけとはいえHyのソースを解明したりして、スリルやショックやサスペンスが花開いたのに、身も蓋もない。

とはいえREPLの実装から想像するに、コードをパースするオーバーヘッドが含まれそうなので、パーサが涙を流して赦しを乞うような重厚長大、複雑怪奇なコードを`timeit`したとき、計測結果の誤差が大きそうです。

# まとめ

HyにもCommon Lispのような`time`マクロがほしい人生でした。

なので、コード片の実行時間計測を実現方法として二通りの方法を提示しました。すなわち、

1. HyのコードをHyのパーサやコンパイラを使ってがんばってPythonコードに変換し、`timeit`関数に渡す
2. Hyのコードを無名関数に包んで、`timeit`関数に渡す

どちらも一長一短といったところなので、ここで編み出した`time`マクロを**使うか使わないかはあなた次第**。