Серьезные накладные расходы в Python cProfile? - PullRequest
Новая
       24

Серьезные накладные расходы в Python cProfile?

5 голосов
/ 28 июня 2010

Привет, эксперты-питонисты, я начинаю использовать cProfile, чтобы получить более подробную информацию о времени моей программы.Тем не менее, меня очень беспокоит, что есть значительные накладные расходы.Любая идея, почему cProfile сообщил 7 секунд, в то время как модуль времени сообщил только 2 секунды в коде ниже? 

# 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())

Ответы [ 2 ]

5 голосов
/ 28 июня 2010

Потому что он делает намного больше работы?time просто умножает всю операцию, в то время как cProfile запускает ее под инструментарием, чтобы получить детальную разбивку.Очевидно, что профилирование не предназначено для использования в производстве, поэтому затраты в 2,5 раза кажутся небольшой ценой.

1 голос
/ 28 июня 2010

Функция f возвращается очень быстро.Когда вы используете cProfile, время, приписываемое одному вызову 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, содержит ошибку, которая теперь не так велика, как общее измеренное время.)

...