Python получает значимые результаты от cProfile

У меня есть сценарий Python в файле, который занимает всего более 30 секунд для запуска. Я пытаюсь профилировать его, поскольку я хотел бы сократить это время резко.

Я пытаюсь профилировать сценарий с помощью cProfile , но, по сути, все, что мне кажется, говорит, что да, основной сценарий занял много времени, но не дает такого рода разбивку, которое я ожидал. На терминале я печатаю что-то вроде:

 cat my_script_input.txt | python -m cProfile -s time my_script.py 

Полученные результаты:

 <my_script_output> 683121 function calls (682169 primitive calls) in 32.133 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 31.980 31.980 32.133 32.133 my_script.py:18(<module>) 121089 0.050 0.000 0.050 0.000 {method 'split' of 'str' objects} 121090 0.038 0.000 0.049 0.000 fileinput.py:243(next) 2 0.027 0.014 0.036 0.018 {method 'sort' of 'list' objects} 121089 0.009 0.000 0.009 0.000 {method 'strip' of 'str' objects} 201534 0.009 0.000 0.009 0.000 {method 'append' of 'list' objects} 100858 0.009 0.000 0.009 0.000 my_script.py:51(<lambda>) 952 0.008 0.000 0.008 0.000 {method 'readlines' of 'file' objects} 1904/952 0.003 0.000 0.011 0.000 fileinput.py:292(readline) 14412 0.001 0.000 0.001 0.000 {method 'add' of 'set' objects} 182 0.000 0.000 0.000 0.000 {method 'join' of 'str' objects} 1 0.000 0.000 0.000 0.000 fileinput.py:80(<module>) 1 0.000 0.000 0.000 0.000 fileinput.py:197(__init__) 1 0.000 0.000 0.000 0.000 fileinput.py:266(nextfile) 1 0.000 0.000 0.000 0.000 {isinstance} 1 0.000 0.000 0.000 0.000 fileinput.py:91(input) 1 0.000 0.000 0.000 0.000 fileinput.py:184(FileInput) 1 0.000 0.000 0.000 0.000 fileinput.py:240(__iter__) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Кажется, это не говорит мне ничего полезного. Подавляющее большинство времени просто перечислены как:

  ncalls tottime percall cumtime percall filename:lineno(function) 1 31.980 31.980 32.133 32.133 my_script.py:18(<module>) 

В my_script.py строка 18 является не чем иным, как закрывающим """ комментарием блока заголовка файла, поэтому дело не в том, что в строке 18 сосредоточен весь объем работы. Скрипт в целом в основном состоит из строки основанную на основном разделении строк, сортировке и настройке, поэтому я ожидал, что большую часть времени вы перейдете к одному или нескольким из этих действий. Поскольку это так, все время, сгруппированные в результатах cProfile, встречаются в комментарии линия не имеет никакого смысла или, по крайней мере, не проливает свет на то, что на самом деле потребляет все время.

EDIT: Я построил минимальный рабочий пример, похожий на мой вышеприведенный случай, чтобы продемонстрировать одно и то же поведение:

mwe.py

 import fileinput for line in fileinput.input(): for i in range(10): y = int(line.strip()) + int(line.strip()) 

И назовите это:

 perl -e 'for(1..1000000){print "$_\n"}' | python -m cProfile -s time mwe.py 

Чтобы получить результат:

  22002536 function calls (22001694 primitive calls) in 9.433 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 1 8.004 8.004 9.433 9.433 mwe.py:1(<module>) 20000000 1.021 0.000 1.021 0.000 {method 'strip' of 'str' objects} 1000001 0.270 0.000 0.301 0.000 fileinput.py:243(next) 1000000 0.107 0.000 0.107 0.000 {range} 842 0.024 0.000 0.024 0.000 {method 'readlines' of 'file' objects} 1684/842 0.007 0.000 0.032 0.000 fileinput.py:292(readline) 1 0.000 0.000 0.000 0.000 fileinput.py:80(<module>) 1 0.000 0.000 0.000 0.000 fileinput.py:91(input) 1 0.000 0.000 0.000 0.000 fileinput.py:197(__init__) 1 0.000 0.000 0.000 0.000 fileinput.py:184(FileInput) 1 0.000 0.000 0.000 0.000 fileinput.py:266(nextfile) 1 0.000 0.000 0.000 0.000 {isinstance} 1 0.000 0.000 0.000 0.000 fileinput.py:240(__iter__) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Я как-то неправильно использую cProfile?

One Solution collect form web for “Python получает значимые результаты от cProfile”

Как я уже упоминал в комментарии, когда вы не можете заставить cProfile работать извне, вы часто можете использовать его внутри. Это не так сложно.

Например, когда я запускаю с -m cProfile в моем Python 2.7, я получаю те же результаты, что и вы. Но когда я вручную использую вашу примерную программу:

 import fileinput import cProfile pr = cProfile.Profile() pr.enable() for line in fileinput.input(): for i in range(10): y = int(line.strip()) + int(line.strip()) pr.disable() pr.print_stats(sort='time') 

… вот что я получаю:

  22002533 function calls (22001691 primitive calls) in 3.352 seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 20000000 2.326 0.000 2.326 0.000 {method 'strip' of 'str' objects} 1000001 0.646 0.000 0.700 0.000 fileinput.py:243(next) 1000000 0.325 0.000 0.325 0.000 {range} 842 0.042 0.000 0.042 0.000 {method 'readlines' of 'file' objects} 1684/842 0.013 0.000 0.055 0.000 fileinput.py:292(readline) 1 0.000 0.000 0.000 0.000 fileinput.py:197(__init__) 1 0.000 0.000 0.000 0.000 fileinput.py:91(input) 1 0.000 0.000 0.000 0.000 {isinstance} 1 0.000 0.000 0.000 0.000 fileinput.py:266(nextfile) 1 0.000 0.000 0.000 0.000 fileinput.py:240(__iter__) 1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Это намного полезнее: он говорит вам, что вы, вероятно, уже ожидали, что более половины вашего времени потрачено на вызов str.strip() .


Также обратите внимание, что если вы не можете редактировать mwe.py , вы всегда можете сделать это:

 import cProfile pr = profile.Profile() pr.enable() import mwe pr.disable() pr.print_stats(sort='time') 

Даже это не всегда срабатывает. Например, если ваша программа вызывает exit() , вам придется использовать try: / finally: wrapper и / или atexit . И он вызывает os._exit() , или segfaults, вы, вероятно, полностью hosed. Но это не очень распространено.


Тем не менее, что-то, что я обнаружил позже: если вы переместите весь код из глобальной области, -m cProfile похоже, работает, по крайней мере, для этого случая. Например:

 import fileinput def f(): for line in fileinput.input(): for i in range(10): y = int(line.strip()) + int(line.strip()) f() 

Теперь выход из -m cProfile включает, среди прочего:

2000000 4.819 0.000 4.819 0.000: 0 (полоса) 100001 0.288 0.000 0.295 0.000 fileinput.py:243(next)

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

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


Еще одна альтернатива, которую я бы не предложил, кроме как в крайнем случае …

Я замечаю, что если я использую профиль вместо cProfile, он работает как внутри, так и снаружи, время зарядки до нужных вызовов. Однако эти вызовы также примерно в 5 раз медленнее. И, как представляется, дополнительные 10 секунд постоянных накладных расходов (которые взимаются за import profile если они используются внутри страны, независимо от того, что включено в строку 1, если они используются снаружи). Итак, чтобы узнать, что split использует 70% моего времени, вместо того, чтобы ждать 4 секунды и делать 2.326 / 3.352, я должен ждать 27 секунд и делать 10.93 / (26.34 – 10.01). Не очень весело …


Последнее: я получаю те же результаты с результатами построения CPython 3.4 dev, когда они используются внутри, и все загружаются в первую строку кода при использовании извне. Но PyPy 2.2 / 2.7.3 и PyPy3 2.1b1 / 3.2.3 оба, кажется, дают мне правильные результаты с -m cProfile . Это может просто означать, что cProfile PyPy подделывается поверх profile потому что код pure-Python достаточно быстр.


В любом случае, если кто-то может понять / объяснить, почему -m cProfile не работает, это было бы здорово … но в остальном это обычно отлично подходит для обхода.

  • Профиль скрипта python с использованием cProfile во внешний файл
  • App Engine: Является ли time.sleep () подсчетом к моим квотам?
  • Как ускорить выбор страниц с urllib2 в python?
  • Профилирование многопроцессорного Python
  • cProfile занимает много памяти
  • Использование результатов cProfile с помощью KCacheGrind
  • Почему модуль cProfile не работает с unittest?
  • Python - лучший язык программирования в мире.