Какова связь между временем процессора, измеряемым профилировщиком Python, и реальным, временем пользователя и sys?

Ответ 1

Это отвечает на подробные сведения о значении реальных, пользовательских и временных таймингов. Цитировать:

• "Реальное" - это часы настенных часов - время от начала до конца вызова. Эта это все прошедшее время, включая срезы времени, используемые другими процессами и время, которое процесс тратит на блокировку (например, если он ожидает ввода-вывода для завершения).

• "Пользователь" - это количество процессорного времени, затраченного на код пользовательского режима (вне ядро) в рамках процесса. Это только фактическое время процессора, используемое в выполнение процесса. Другие процессы и время, которое тратит процесс заблокированы, не рассчитывайте на эту цифру.

• "Sys" - это количество времени процессора, затраченного на ядро ​​в процессе. Это означает выполнение времени CPU, затрачиваемого на системные вызовы в пределах ядра, в отличие от библиотечного кода, который все еще работает в пользовательское пространство. Подобно "пользователю", это только процессорное время, используемое процессом.

Из приведенного выше объяснения оно выглядит так, как время User + Sys должно быть равным секундам CPU. Вместо этого он ближе к "реальному" времени. Странный!

Это справедливое объяснение. Время "Пользователь" не включает в себя секунды ЦП, затраченные на операции ввода-вывода в процессе. Это просто измеряет время процессора, затрачиваемое на код пользовательского режима в памяти. Эмпирическое правило:

real time = user + sys + время ввода/вывода + время запуска интерпретатора + время компиляции байткода

Чтобы проверить это, я сделал вызов urllib2.urlopen(urllib2.Request(url)) для интенсивного ввода-вывода. Вот результаты:

         100792 function calls (98867 primitive calls) in 2.076 CPU seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      512    0.719    0.001    0.719    0.001 {method 'recv' of '_socket.socket' objects}
        1    0.464    0.464    0.473    0.473 {_socket.getaddrinfo}
        1    0.352    0.352    0.352    0.352 <string>:1(connect)
        1    0.248    0.248    0.348    0.348 common_functions.py:1(<module>)
        1    0.022    0.022    0.075    0.075 __init__.py:2(<module>)
        1    0.017    0.017    0.030    0.030 urllib.py:1442(getproxies_macosx_sysconf)
   330/67    0.012    0.000    0.031    0.000 sre_parse.py:385(_parse)


real    0m2.255s
user    0m0.352s
sys 0m0.093s

Здесь в операциях ввода-вывода (главным образом _socket.socket и _socket.getaddrinfo) потреблялось 2.076- (0.352 + 0.093), т.е. 1,631 CPU secs. Остальное время, 2.255-2.076, были потрачены на холодный старт кода.

Надеюсь, что это было полезно.

Обновление. В нескольких ядрах, где несколько процессоров работают параллельно, случай немного отличается. Общее количество секунд CPU, о которых сообщает cProfile, - это сумма времени, затрачиваемого всеми процессорами в отдельности. Например, в двухъядерной системе, если один процессор работает в течение 10 секунд. Параллельно другой процессор работает в течение 15 секунд. Общее количество секунд CPU будет составлять 25 секунд. Хотя время в реальном времени может составлять всего 15 секунд. Следовательно, время процессора может быть больше, чем в режиме реального времени в многоядерных системах. Поскольку процессоры работают параллельно

Ответ 2

Я был озадачен той же проблемой.

Ответ заключается в том, что cProfile использует время разгона. И его результат был исторически ошибочным, но теперь он исправлен ( "CPU" в "CPU seconds" был удален). Я не знаю точно, когда, но Python 2.6.6 в Debian 6.0 имеет ошибку, в то время как Python 2.7.3 в Debian 7.0 в порядке.

Это вызывает недоумение, потому что большинство времени профилировщиков тратится на процессор, а не на время разгона. Но это "дешевый" профилировщик.

Документ http://docs.python.org/2/library/profile.html#limitations объясняет - непонятно - что время основано на тикающем развороте, а не методах getrusage() или ptrace.

Если вы проверите код (http://hg.python.org/cpython/file/44f455e6163d/Modules/_lsprof.c), вы можете проверить, что он основан на QueryPerformanceFrequency/gettimeofday.

Jerrymouse прав насчет того, что тайм-ауты времени и времени не могут совпадать, потому что cProfile запускается только после компиляции кода. Но кроме того, его "реальное" уравнение является фиктивным.

Разница между wallclock и user + sys может заключаться во множестве разных факторов, таких как ввод-вывод от имени вашего процесса или от имени любых других процессов, включая само ядро ​​(свопинг, ведение журнала и т.д.) или время процессора потраченные на другие процессы или ожидающие чего-либо от имени вашего процесса, которые не могут быть учтены, поскольку это удаленный ressource (сетевой или косвенный через NFS или iSCSI) и т.д. Вы называете это.

Ответ 3

Профилер Python по умолчанию измеряет время стены, но может быть сделан для измерения времени процессора с использованием пользовательской функции таймера. Следующие работы работают под Linux, но не Windows (поскольку time.clock измеряет время на стене в Windows):

import cProfile
import time


def idleWait():
    time.sleep(10)

def busyWait():
    t = time.time() + 10
    while time.time() < t: pass

def target():
    idleWait()
    busyWait()


print "Wall time:"
p = cProfile.Profile()
p.runcall(target)
p.print_stats()

print "CPU time:"
p = cProfile.Profile(time.clock)
p.runcall(target)
p.print_stats()

Первый прогон профиля покажет 20 секунд, причем около половины из них потрачено на time.sleep. Второй показывает 10 секунд, и ни один из них не провел в time.sleep.