Один и тот же код Python имеет разные характеристики производительности.

Question

Один и тот же код Python имеет разные характеристики производительности.

Описание

В моем коде для создания N случайные строки длины k, выражение генератора для создания случайного k-символьная строка вызывается либо N+1 или (N+1)*k (он же N*k+N) раз. Похоже, это происходит с одним и тем же кодом, и я могу переключаться туда и обратно, казалось бы, недетерминированно, переопределяяchrs()вспомогательная функция. Я подозреваю профилировщика, но понятия не имею о механизме.

Сведения о системе, если они имеют значение: CPython, Python 2.7.17 и Python 3.6.9 в Ubuntu 18.04 на HP Envy 15k (i7-4720)

Воспроизведение выпуска

Не правильный MCVE, так как я не смог детерминированно воспроизвести проблему; вместо этого, мы надеемся, что это приведет к одному из двух выходных данных профилировщика ниже. Если вы попробуете запустить это в REPL и переопределитьchrs() многократно используя один и тот же код, вы можете получить оба выхода профилировщика.

Я написал это bits_strings() функции при тестировании различных способов генерации N (num_strings) случайные строки длины k (len_string):

import cProfile
import random
import string

def chrs(bits, len_string):
    return ''.join(chr((bits >> (8*x)) & 0xff) for x in range(len_string))

def bits_strings(num_strings, len_string):
    return list(
        chrs(random.getrandbits(len_string*8), len_string)
        for x in range(num_strings)
    )

cProfile.run('bits_strings(1000, 2000)')

Для сравнения я использовал cProfile.run().

Когда я запустил код в первый раз, он показался мне довольно быстрым:

cProfile.run('bits_strings(1000, 2000)')
         2005005 function calls in 0.368 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.970    1.970 <stdin>:1(bits_strings)
     1000    0.001    0.000    1.963    0.002 <stdin>:1(chrs)
     1001    0.001    0.000    1.970    0.002 <stdin>:2(<genexpr>)
        1    0.000    0.000    1.970    1.970 <string>:1(<module>)
  2000000    0.173    0.000    0.173    0.000 {chr}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
     1000    0.005    0.000    0.005    0.000 {method 'getrandbits' of '_random.Random' objects}
     1000    0.178    0.000    1.953    0.002 {method 'join' of 'str' objects}
     1001    0.009    0.000    0.009    0.000 {range}

но позже в тот же день:

cProfile.run('bits_strings(1000, 2000)')

         4005004 function calls in 1.960 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.961    1.961 <stdin>:1(bits_strings)
     1000    0.001    0.000    1.954    0.002 <stdin>:1(chrs)
  2001000    1.593    0.000    1.762    0.000 <stdin>:2(<genexpr>)
        1    0.000    0.000    1.961    1.961 <string>:1(<module>)
  2000000    0.170    0.000    0.170    0.000 {chr}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
     1000    0.005    0.000    0.005    0.000 {method 'getrandbits' of '_random.Random' objects}
     1000    0.182    0.000    1.944    0.002 {method 'join' of 'str' objects}
     1001    0.009    0.000    0.009    0.000 {range}

Разница, похоже, исходит от <genexpr>, который - из cumtime и местоположение в различных аналогичных тестах, я решил, что это chrs(). (Мой инстинкт таков, что(chr((bits >> (8*x)) & 0xff) for x in range(len_string)) должен быть вызван N раз, пока chr((bits >> (8*x)) & 0xff) должен быть вызван N*k раз).

Так в чем разница между двумя bits_strings()функции? Пытаясь найти разницу в коде между двумя попытками, я ничего не нашел. Фактически, у меня был сеанс Python REPL, в котором я определил функции, дважды запустил профилировщик (второй раз, чтобы проверить, была ли это проблема кеширования), а затем повторно определил функции, используя стрелку вверх, чтобы получить мои ранее введенный код. Он показал такое же расхождение: https://pastebin.com/1u1j1ZUt

Теории и мысли

EDIT: я подозреваю, что cProfile сейчас.

Переключение между "быстрой" и "медленной" версиями путем переопределения chrs() но имел cProfile.run() профилировать cProfile.run(). Как в наблюдаемое время, так и во внешнемcProfile.run()репортаж, похоже, что внутренний cProfile.run() (тот, который профилирует bits_strings()) иногда занижал, как долго bits_strings()берет: https://pastebin.com/C4W4FEjJ

Я также использовал time.time() до после cProfile.run('bits_strings(1000,1000)) звонит и заметил несоответствие между "быстрым" профилем cumtime и фактическое время настенных часов, затраченное при запуске метода.

По-прежнему неясен механизм.

Кеширование: один и тот же код, резко различающаяся производительность между запусками может быть связана с кешированием. Однако быстрая версия была первым запуском, который я когда-либо выполнял с этим кодом (хотя я раньше запускал другой код в том же сеансе REPL). И я могу переключаться с медленного на быстрое или с быстрого на медленное, просто переопределивchrs() а также bits_strings(), хотя, действительно ли я переключаюсь, кажется случайным. Также стоит отметить, что я смог переключить (afaict) только переопределив функции, а не просто перезапустив их. Поэтому я не уверен, что будет кэшироваться или как это изменит количество<genexpr> звонки с коэффициентом k при переопределении функции.
Причуда cProfile: я запустил тот же код безcProfile.run() и рассчитал его, получив текущий time.time() внутри bits_stringsдважды; общее время было сопоставимо сcProfile.run()для медленного случая. ТакcProfile.run()по крайней мере, не замедляет работу. Есть вероятность, что быстрый результат испорченcProfile.run(),, Но эпизодически при больших значенияхN а также k ((10000, 10000)) Я заметил ощутимую разницу между первым запуском bits_strings()и медленный позже в тот же день.
причуда интерпретатора: я думал, что это могло произойти из-за того, что интерпретатор неправильно оптимизировал выражения генератора внутриchrs() а также bits_strings(), но это интерпретатор CPython, который платит за то, что вы пишете, так что это кажется маловероятным.
Причуда Python 2.7: новое определениеchrs() (используя стрелку вверх для получения предыдущего определения) непоследовательно выполняет тот же трюк в python3: https://pastebin.com/Uw7PgF7i
Залго собирается отомстить за то, что однажды я проанализировал HTML с помощью регулярного выражения: не исключено

Мне хочется верить, что bits_strings()в разное время (разные определения одной и той же функции с одним и тем же кодом, а не разные прогоны) фактически выполнялись по-разному. Но я понятия не имею, почему это могло быть так. Я подозреваю, что это больше связано сchrs() чем это bits_strings().

Я не понимаю, зачем переопределять chrs() кажется, непредсказуемо влияет на вывод профилировщика.

2

python cprofile python-performance

Источник

user13632026 28 май '20 в 08:52

1 ответ

Решение

Другие вопросы по тегам python cprofile python-performance

user2357112 28 май '20 в 10:02 2020-05-28 10:02 · Accepted Answer · 2020-05-28 10:02

Это артефакт отчета о результатах cProfile, который не может различить два объекта кода с одинаковым именем, именем файла и номером строки.

При сборе статистики статистика сохраняется в бинарном дереве поиска с произвольной перебалансировкой, которое, по-видимому, является вариантом рандомизированного развернутого дерева. Адреса памяти объекта кода используются в качестве ключей для функций Python (и адресов памяти PyMethodDef для функций C).

Однако по завершении профилирования данные реорганизуются в dict, используя кортежи (имя файла, номер строки, имя объекта кода) в качестве ключей для функций Python. Это теряет информацию в случаях, когда эти ключи не уникальны, например, в вашем примере. В таких случаях объект кода с наивысшим адресом памяти обрабатывается последним, поэтому этот объект кода является тем, чья статистика появляется в результирующем dict.

В ваших тестах вы видите статистику по генэксп в chrs или генэксп в bits_strings. Какие статистические данные вы видите, зависит от того, какой объект кода genexp имеет более высокий адрес памяти.

Если бы вы запускали свой код как скрипт, а не в интерактивном режиме, genexps можно было бы различить по номеру строки, и в результате появились бы оба genexps. В интерактивном режиме номера строк перезапускаются для каждой "единицы" кода, введенной в интерактивном режиме (одна>>> подсказка и все последующие ...подсказки). Однако бывают случаи, когда этот артефакт профилирования может возникать не интерактивно, например, с двумя генэкспами в одной строке или двумя файлами с одинаковыми именами.