5

こんにちは、専門家の Pythonists です。プログラムのより詳細なタイミング情報を取得するために、cProfile を使用し始めています。ただし、かなりのオーバーヘッドがあることは非常に気がかりです。以下のコードで、time モジュールが 2 秒しか報告していないのに、cProfile が 7 秒を報告した理由は何ですか?

# a simple function

def f(a, b):
 c = a+b

# a simple loop
def loop():
 for i in xrange(10000000):
  f(1,2)

# timing using time module
# 2 seconds on my computer
from time import time
x = time()
loop()
y = time()
print 'Time taken %.3f s.' % (y-x)

# timing using cProfile
# 7 seconds on my computer
import cProfile
cProfile.runctx('loop()', globals(), locals())
4

2 に答える 2

5

それはより多くの仕事をしているからですか？ 詳細な内訳を取得できるように、インストルメンテーションの下で実行しtimeながら、操作全体の時間を計測します。cProfile明らかに、プロファイリングは本番環境での使用を意図したものではないため、2.5 倍のオーバーヘッドはわずかな代償のように思えます。

于 2010-06-28T17:59:11.053 に答える
1

関数fは非常に迅速に戻ります。cProfile を使用する場合、1 回の呼び出しに起因するf時間は正確ではありません。時間は非常に小さいため、時間測定の誤差に匹敵します。時間の差を測定するために使用されるクロックは、0.001 秒までしか正確でない場合があります。したがって、各測定の誤差は、測定しようとしている時間よりも桁違いに大きくなる可能性があります。これを 1e7 回行うと、偽の結果が得られます。(これに関する詳細については、 http://docs.python.org/library/profile.html#limitationsを参照してください。)

使用するコードを変更すると、

def f(a, b):
 for i in xrange(int(1e4)):    
     c = a+b

# a simple loop
def loop():
 for i in xrange(int(1e3)):
  f(1,2)

あなたが得る

Time taken 0.732 s.
         1003 function calls in 0.725 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.725    0.725 <string>:1(<module>)
     1000    0.723    0.001    0.723    0.001 test.py:4(f)
        1    0.001    0.001    0.725    0.725 test.py:9(loop)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

同じ数のループを実行していますが、各呼び出しにf時間がかかります。これにより、測定ごとのエラーが削減されます。(各呼び出しに起因する時間にfは、測定された合計時間ほど大きくないエラーが含まれています。)

于 2010-06-28T19:07:40.120 に答える