これはiRidge Advent Calendarの八日目の記事です。

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

動機

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

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

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

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

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

>>> 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! Hyでやってみましょう。

=> (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のコードをぼんやりと眺めてみます。

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

# 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()がありました！

# 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で確認してみますと…

=> (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に投げられそうです。

=> (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()を覗いてみましょう。

# 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という、ASTを操作したりコードに変換したりするモジュールがあるのですね。いつ役立つかよくわからない学びがありました。

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

=> (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関数へと脱線しましたが、それは割愛します。文字列に変換する必要はなかった!!hy-compile関数のdocstringを落ち着いて読めばわかりました。

Compile a HyObject tree into a Python AST Module.

そして

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

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

=> (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'
...

怒られました。ただのHyObjectではなく、行番号も足してやらないといけないっぽいです。hy/core/language.pyにそれっぽい関数があるのでこいつでラップして渡すと、

=> (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につっこみます。

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

空。空文字列。

ちなみに、このモジュールの-pprintを使って文字列化したものをtokenize、hy-compileしたものはPythonコードが出力されることは確認済みです。無駄足。

方針変更です。

結局

fake-source-positionsを探してるときに、HyコードをPython文字列に変換する関数が標準で用意されていることに気付きました。いままでの苦労がぜんぶ水泡に帰した気分でシアワセです。

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

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

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

ふう。

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

=> (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モジュールのイカの箇所をぼけーっと眺めていて気付きました。

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

はい。

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

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

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

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

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

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

まとめ

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

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

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

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

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

動機