プロファイリング

ここでは、Cython のプロファイリング機能を解説します。pure Python コー ドのプロファイリングに詳しいなら、最初の節 (Cython でのプロファイリングの基本) を読むだけで大丈夫です。そうでないなら、チュートリアル (チュートリアル) も読んで、例題に一つづつ目を通していきましょ う。

Cython でのプロファイリングの基本

Cython のプロファイリングはコンパイラディレクティブで制御します。プロ ファイリングはファイル全体に対しても、一つの関数に対しても設定できます。 関数に対して設定するときは、 Cython のデコレータを使います。

ソースファイル全体にわたってプロファイリングを有効にする

ファイル全体にわたるプロファイリングを制御するには、ファイルのトップレ ベルでグローバルディレクティブを使います:

# cython: profile=True

プロファイリングを有効にすると、関数呼び出しのたびにわずかなオーバヘッ ドが生じるので、プログラムは微妙に (小さな関数をきわめて頻繁に呼び出す ようなプログラムでは、かなり) 遅くなります。

プロファイリングを有効にした Cython のコードは cProfile モジュールから 呼び出した Python コードと同じように振る舞います。従って、Python コー ド単体のプロファイリングに使うのと同じツールを使って、 Cython のコード と Python のコードを一緒にプロファイルできます。

プロファイリングを関数単位で無効化する

一部の小さな関数が、呼び出しのオーバヘッドを生むことでプロファイリング 全体を台無しにしてしまう場合があります。それでいて、プロファイリングの 必要はあまりない場合 - 最終的にインライン化するつもりだったり、もう高 速化は望めないと確認した場合 - には、専用のデコレータを使って、関数一 つの単位でプロファイリングを無効にできます:

cimport cython

@cython.profile(False)
def my_often_called_function():
   pass

チュートリアル

このチュートリアルでは、Python コードをプロファイリングして Cython コー ドに改造し、十分高速になるまでプロファイリングする一連の流れを全て解説 します。

例として、ある整数 n までの平方数の逆数を加算して、 \pi を計算するアルゴリズムを考えます。この関係式は、 1735 年に オイラーが証明した、いわゆる バーゼル問題 (Basel problem) で知ら れています。

\pi^2 = 6 \sum_{k=1}^{\infty} \frac{1}{k^2} = 6 \lim_{k \to \infty} \big( \frac{1}{1^2} + \frac{1}{2^2} + \dots + \frac{1}{k^2} \big) \approx 6 \big( \frac{1}{1^2} + \frac{1}{2^2} + \dots + \frac{1}{n^2} \big)

部分和を計算する Python コードは以下のように書けます:

#!/usr/bin/env python
# encoding: utf-8
# filename: calc_pi.py

def recip_square(i):
    return 1./i**2

def approx_pi(n=10000000):
    val = 0.
    for k in range(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

私の環境では、 n がデフォルト値のとき、このコードの実行 には約 4 秒かかります。 n を大きくすればするほど、値は \pi に 近づきます。経験豊かな Python プログラマなら、すでにこのコードを最適化 する方法をたくさん思いついていることでしょう。しかし、最適化の大原則、 プロファイリングせざるもの 決して 最適化すべからず、を思い出してく ださい。このコードのどこに時間がかかり過ぎているのか、に関する考えは 往々にして誤っています。すくなくとも、私に関していえばいつもそうです。 というわけで、ちょっとしたスクリプトを書いてコードをプロファイリングし てみましょう:

#!/usr/bin/env python
# encoding: utf-8
# filename: profile.py

import pstats, cProfile

import calc_pi

cProfile.runctx("calc_pi.approx_pi()", globals(), locals(), "Profile.prof")

s = pstats.Stats("Profile.prof")
s.strip_dirs().sort_stats("time").print_stats()

私の環境では、以下のように出力されました

Sat Nov  7 17:40:54 2009    Profile.prof

         10000004 function calls in 6.211 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    3.243    3.243    6.211    6.211 calc_pi.py:7(approx_pi)
 10000000    2.526    0.000    2.526    0.000 calc_pi.py:4(recip_square)
        1    0.442    0.442    0.442    0.442 {range}
        1    0.000    0.000    6.211    6.211 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

ここには、コードの実行に CPU 時間で 6.2 秒費やしたという情報が入ってい ます。コードが cProfile モジュール中で実行されたため、 2 秒ほど遅くなっ ています。その下の表には、極めて有用な情報が入っています。 profile のドキュメント (profiling documentation) を読んで、プロファイル結果の詳しい見方を調べてみてください。 もっとも重要なカラムは tottime (関数を実行するのにかかった時間であって、 関数内で呼び出した別の関数の実行時間を 計上しない もの) と cumtime (関数を実行するのにかかった時間であって、関数内で呼び出した別の関数の 実行時間も 計上した もの) です。 tottime カラムを見れば、実行時間 のほぼ半分が approx_pi で費やされていて、残りが recip_squate で費やさ れていることがわかります。また、 range にも約 0.5 秒が費やされています。 このような大きい数のイテレーションを行うには xrange を使うべきでしたね... 実際、range を xrange に変えると、コードは約 5.8 秒で動作しました。

pure Python 版でも色々と最適化できるのでしょうが、ここでは Cython が話 題なので、とにかくこのモジュールを Cython に持ってきましょう。同時に、 一手間入れてループが高速に実行される形にしておきます。最初の Cython 版 は以下のようになります:

# encoding: utf-8
# cython: profile=True
# filename: calc_pi.pyx

def recip_square(int i):
    return 1./i**2

def approx_pi(int n=10000000):
    cdef double val = 0.
    cdef int k
    for k in xrange(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

コードの2行目に注意してください。プロファイリングを有効にするには、 Cython にそのことを教えねばなりません。プロファイリングによって Cython のコードはちょっと遅くなりますが、そうしないと cProfile モジュールから 意味のある出力を引き出せません。それ以外のコードは基本的に変えず、変数 の一部の型を宣言して、少しだけ高速化しておきました。

プロファイリングスクリプトも、Cython モジュールを直接実行するように書 き換える必要があります。 pyximport モジュールの import を追加したバー ジョンを以下に示します:

#!/usr/bin/env python
# encoding: utf-8
# filename: profile.py

import pstats, cProfile

import pyximport
pyximport.install()

import calc_pi

cProfile.runctx("calc_pi.approx_pi()", globals(), locals(), "Profile.prof")

s = pstats.Stats("Profile.prof")
s.strip_dirs().sort_stats("time").print_stats()

プロファイリングスクリプトに追加したのは 2 行だけで、それ以外は変えて いません。手動でコードを拡張モジュールにコンパイルするという方法もあり ます。その場合、プロファイリングスクリプトを変更する必要は全くありませ ん。今度は、スクリプトの実行結果は以下のようになりました:

Sat Nov  7 18:02:33 2009    Profile.prof

         10000004 function calls in 4.406 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    3.305    3.305    4.406    4.406 calc_pi.pyx:7(approx_pi)
 10000000    1.101    0.000    1.101    0.000 calc_pi.pyx:4(recip_square)
        1    0.000    0.000    4.406    4.406 {calc_pi.approx_pi}
        1    0.000    0.000    4.406    4.406 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

1.8 秒短縮しました。悪くないですね。前のプロファイリング結果と比べると、 recip_square 関数が高速化された一方、 approx_pi はあまり変わっていない ことが分かります。そこで、ちょっと recip_square に専念することにしましょ う。まず、この関数はモジュールの外部から呼び出されることはないので、 関数呼び出しのオーバヘッドをなくすために cdef に変えるのが懸命です。 また、べき乗演算子も排除すべきです: Cython はべき乗演算を pow(i,2) と いう関数呼び出しに置き換えますが、単に i*i と書いた方が速いはずです。 また、この関数全体がインライン化の格好の対象です。そこで、これらのアイ デアを取り込んで以下のような変更を施します:

# encoding: utf-8
# cython: profile=True
# filename: calc_pi.pyx

cdef inline double recip_square(int i):
    return 1./(i*i)

def approx_pi(int n=10000000):
    cdef double val = 0.
    cdef int k
    for k in xrange(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

さあ、プロファイリングを行うと、結果は以下のようになります:

Sat Nov  7 18:10:11 2009    Profile.prof

         10000004 function calls in 2.622 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.782    1.782    2.622    2.622 calc_pi.pyx:7(approx_pi)
 10000000    0.840    0.000    0.840    0.000 calc_pi.pyx:4(recip_square)
        1    0.000    0.000    2.622    2.622 {calc_pi.approx_pi}
        1    0.000    0.000    2.622    2.622 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

さらに 1.8 秒短縮できました。とはいえ、びっくりするほど劇的な変化とい うわけではありませんね。それに、recip_square がまだテーブルに表示され ています。これ、インライン化されるはずでしたよね? これは、関数呼び出しがなくなった後も、 Cython がプロファイリングコード を挿入しているからです。そこで、 recip_square をこれ以上プロファイリン グしないように Cython に指示しましょう。この関数は、もうこれ以上高速化 できません:

# encoding: utf-8
# cython: profile=True
# filename: calc_pi.pyx

cimport cython

@cython.profile(False)
cdef inline double recip_square(int i):
    return 1./(i*i)

def approx_pi(int n=10000000):
    cdef double val = 0.
    cdef int k
    for k in xrange(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

今度は、興味深い結果が出ました:

Sat Nov  7 18:15:02 2009    Profile.prof

         4 function calls in 0.089 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.089    0.089    0.089    0.089 calc_pi.pyx:10(approx_pi)
        1    0.000    0.000    0.089    0.089 {calc_pi.approx_pi}
        1    0.000    0.000    0.089    0.089 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

まずは、大幅な高速化が得られたことに注意してください。このバージョンの 実行には、最初の Cython 版の 1/50 の時間しかかかっていません。それに、 recip_square は期待通りテーブルから消えています。しかし、もっとも奇妙 で、かつ重要な変化は、 approx_pi も高速化したという点です。 これは、プロファイリングを行う時につねについてまわる問題です: プロファ イリングの実行中に関数呼び出しを行うと、関数呼び出し自体に一定のオーバ ヘッドが追加されます。このオーバヘッドは、呼び出された関数側の実行時間 に加算されるの ではなく呼び出した側 の関数の費やした時間と して計上されるのです。 今回の例では、実行に 2.622 秒を要していたのは approx_pi 自体ではありま せんでした。ただ、 recip_square を 10000000 回呼び出していたので、毎回 プロファイリングをセットアップする僅かな時間を費やしていたのです。 それが積み重なって、約 2.6 秒ものタイムロスにつながっていたというわけ です。何度も呼び出される関数のプロファイリングを止めると、 approx_pi が費やしている時間の実像があらわになります。これで、必要に応じて最適化 の作業をつづけていくことができるというわけです。

さて、プロファイリングのチュートリアルはここまでとしましょう。このコー ドにはまだ若干改善の余地があります。例えば、 approx_pi 中のべき乗演算 を C の標準ライブラリの sqrt に置き換えるといった具合です。ただ、そう したところで、必ずしも pow(x,0.5) より早くなるとは限りません。

いずれにせよ、ここまでの作業で、十分満足できる結果にたどり着いたと思い ます。オリジナルの Python 版から、機能を削らず、可読性も失わないまま高 速化するという結果を得たのですから。