次の短いプログラムを Windows と Linux で実行してみると面白いことが分かります。

Windows 版の場合、出てくる値と値の間がそれぞれ0.0010秒程度(100,000ループさせているのに32回しかそもそも値が表示されません)。これに対して、Linux で試すと 0.000017秒～0.000020 秒程度ごとに表示されるのです(100,000行表示される)。つまり、Linux で試すと、そもそも time.time() が 0.0000020秒(より短い)ぐらいで実行できるので、ループが回ってくるたびにちゃんと異なる時間を返してくれています。そうしたわけで、実行環境によってもやや状況は変わるかもしれませんが、Windows 版の Python だと time.time() を使うと、あまり時間を正確に測ることができないということになるようです。

#!/usr/bin/env python
# -*- encoding: utf-8 -*-

import time

i = 100000  # 100000 回試す

# 時刻 t1 を設定
t1 = time.time() 

while i:
    # 時刻 t2 を設定
    t2 = time.time() 

    # t1 と t2 で差があれば、表示する。
    # 差がなければ0なので表示されない。
    if t2 - t1:  
        print t2, t2 - t1
        # t1 に新しい時刻を設定しなおす。
        t1 = t2
    # ループカウンタを減らす
    i -= 1

ちなみに、次のように、単純に time.time() を 100000 回繰り返すだけのプログラムを実行してみると、Windows 0.231000065804秒、Linux 0.182734966278秒と、やや Linux の方が速いです。といっても、実は Windows の方が Linux のマシンより CPU 自体が遅いので正確ではありません。それでも、1.3 倍にも満たないわけで、オーダーがぜんぜん違うことの説明になりません。Windows 版の Python の time.time() はダメということになります。速度が遅いというわけではなく、精度が粗いということになります。

#!/usr/bin/env python
# -*- encoding: utf-8 -*-

import time

i = 100000
t1 = time.time()

while i:
    i -= 1
    time.time()

t2 = time.time()
print t2 - t1

なぜこういうことになってしまうのでしょう。Windows が OSレベルでダメなのでしょうか。こういうレベルのことは、今まで関心がなかったので気にしていませんでした。そこで、少し調べてみることにしました。運よく、RunTime: LinuxおよびWindows 2000におけるハイパフォーマンス・プログラミング手法にちょうどよい記事が見つかりました。

Windows 2000には、時間を測定する2つのAPIがあります。1つはGetTickCount()です。この関数は、システムがブートされてから経過した時間をミリ秒単位で報告します。GetTickCount()には、「クロック・ティック」精度があります。つまり、システム・クロックが刻まれたときだけ更新されるということです。Windowsの場合は、10ミリ秒ごとに更新されるだけです。そのためクロック・ティック精度は、最高でも10ミリ秒すなわち 10,000マイクロ秒程度です。

という理由によって、GetTickCount() を使っているようであれば、まず、その点で問題がありだということになります。GetTickCount を使っている限り、10ミリ秒単位でしか計測できないということになるからです。もう少し見てみると、

Windows 2000にはまた、64ビット高精度パフォーマンス・カウンターの現行値を取り出すQueryPerformanceCounter() APIがあります。QueryPerformanceCounter()に対するコールの結果に含まれるそれぞれの「ティック」が表す内容は、 QueryPerformanceFrequency()が返す値で決まります。頻度数は、1秒当たりのカウンター増加数であり、したがって秒は次のように表されます。

QueryPerformanceCounter を使って「カウンタの値/1秒あたりのカウンタ増加数」のような感じになっていれば、この記事と同様の精度になってくれるはずです。

同じハードウェア上でWindows 2000のQueryPerformanceCounter()システム・コールは、Linuxのgettimeofday() APIよりも速度がはるかに遅いということです。今回の目的には、タイミング・ルーチンの2マイクロ秒という精度で十分です。

Windows でも、一応、2マイクロ秒の精度で、タイミング・ルーチンが書けるということになります。ということは、Python のソースで、GetTickCount を使っているか、QueryPerformanceCounter を使っているかをまずチェックしてみればよいと思い、Python のソースを grep してみると、GetTickCount は使っていないようです。QueryPerformanceCounter は _hotshot.c と、timemodule.c で使われています。Linux の場合は gettimeofday が使われています。そうであれば、理屈上 Linux の倍程度ではあっても、もう少し Windows 版の時間の粒度が細かくなってもよさそうなものなのに、なぜなのでしょう。_hotshot.c を見ると、MS_WIN32 の場合、次のようになっているので、上記の記事と同じような手法を使っているように見えます。

#ifdef MS_WIN32
#include 
#include 
#include     /* for getcwd() */
typedef __int64 hs_time;
#define GETTIMEOFDAY(P_HS_TIME) \
        { LARGE_INTEGER _temp; \
          QueryPerformanceCounter(&_temp); \
          *(P_HS_TIME) = _temp.QuadPart; }


HAVE_GETTIMEOFDAY

static char resolution__doc__[] =
#ifdef MS_WIN32
"resolution() -> (performance-counter-ticks, update-frequency)\n"
"Return the resolution of the timer provided by the QueryPerformanceCounter()\n"
"function.  The first value is the smallest observed change, and the second\n"
"is the result of QueryPerformanceFrequency().";
#else
"resolution() -> (gettimeofday-usecs, getrusage-usecs)\n"
"Return the resolution of the timers provided by the gettimeofday() and\n"
"getrusage() system calls, or -1 if the call is not supported.";
#endif

time_clock(PyObject *self, PyObject *args)など見ながら、ふと考えてみると時間の間隔を測りたいわけではないのだから、time.clock() を使えばいいと気がつきました。これで試してみると、0.0000282秒程度で、100,000行ちゃんと表示されるようになりました。ということで、これから、Windows で時間測定をするときは、time.clock() でプロセス開始からの時間をチェックするようなやり方をしようと思う。しかし、なぜ time.time() だと精度がそんなに違うのでしょう。time_time(PyObject *self, PyObject *args)を見てみると、secs = floattime(); に問題がありそうな気がしてきます。

static double
floattime(void)
{
        /* There are three ways to get the time:
          (1) gettimeofday() -- resolution in microseconds
          (2) ftime() -- resolution in milliseconds
          (3) time() -- resolution in seconds

(2) に流れてしまっているようです。しかし、今頃、バグということはないでしょう。ということで、また検索をしてみると Python ライブラリリファレンス 10.10 timeitが見つかりました。

Windows の場合、 time.clock() はマイクロ秒の精度がありますが、 time.time() は 1/60 秒の精度しかありません。一方 Unixの場合、time.clock() でも 1/100 秒の精度があり、 time.time() はもっと正確です。いずれのプラットフォームにおいても、デフォルトのタイマ関数は CPU 時間ではなく通常の時間を返します。つまり、同じコンピュータ上で別のプロセスが動いている場合、タイミングの衝突する可能性があるということです。

ここに最初から答えがありました。考えてみると、QueryPerformanceCounter はあくまでカウンタだから時間をとることができません。ですから、時刻をとる場合は、ftime() を使わざるを得ないということなのでしょう。しかし、起動時の時刻を保存しておいて、カウンタから求めた時間を足してやったらどうなのだろうと思って試してみることにしました。

import time

#基本の時刻を取得しておいて
#クロックを開始する
BASETIME= time.time()
time.clock()

def _mytime():
    global BASETIME
    return time.clock() + BASETIME

time.time = _mytime

このように time.time を上書きして置き換えてしまえば、呼び出しごとに確実に異なる時間が返ることが保証できそうです。ただし、100000回の呼び出しテストをしてみる time.time() < time.clock() < _mytime() の順にと、0.241000056267 , 0.340696932152, 0.514129638672 となって、ほんものの time.time() にくらべて偽ものは倍の実行時間がかかってしまいます。それでも、時刻としてできるだけきめ細かくとりたいときは、そうするしかないのではないかと思います。1回呼び出しするときのコストは、0.00002秒程度と換算できます。ただ、パフォーマンステストで時間を細かくとるなら、時刻ではなく時間の差分だけ分かればよいのですから time.clock でいいわけでしょう。
細かく時間をとる必要がない場合は、本物の time.time() を使って、時刻を使って値を作り出したいときなど、time.time() より細かく時刻をとりたい場合は、ニセモノでやることにしました。Zope などは、time.time() を内部でたくさん使っているようですが、Windows 版だと問題になることはないのでしょうか、ちょっと気になるところです。誰も問題にしないということは、それでも大丈夫なようにちゃんとできているということなのかもしれません。すくなくとも、Zope のプロダクトにある CallProfiler みたいなものを使った場合、正確な値はとれないとは思いますが...。なにはともあれ原因が分かってすっきりしました。

それ以前に、パフォーマンスの測定したいなら不精をして time.time() で時刻の差分をとるなどせずに、プロファイラをちゃんと使えば、よいという話もあります。Python 2.3 でプロファイラも改善されているようです。しかし、なんなのでしょうね、このオチは。Python のマニュアルを最初から全部読んでいれば、問題はなかったのに。