Увеличение глубины cProfiler в Python, чтобы сообщить больше функций? - PullRequest
Новая
       29

Увеличение глубины cProfiler в Python, чтобы сообщить больше функций?

9 голосов
/ 20 декабря 2010

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

from mymodule import foo
def start():
   # ...
   foo()

import cProfile as profile
profile.run('start()', output_file)
p = pstats.Stats(output_file)
print "name: "
print p.sort_stats('name')
print "all stats: "
p.print_stats()
print "cumulative (top 10): "
p.sort_stats('cumulative').print_stats(10)

Я обнаружил, что профилировщик говорит, что все время было потрачено в функции "foo ()" моего модуля, вместо того, чтобы разбивать его на вызовы подфункций foo (), что я и хочу увидеть. Как я могу заставить профилировщик сообщать о производительности этих функций?

спасибо.

Ответы [ 3 ]

0 голосов
/ 24 марта 2016

Вам нужно p.print_callees(), чтобы получить иерархическую разбивку вызовов методов.Вывод не требует пояснений: в левом столбце вы можете найти интересующую вас функцию, например, foo(), затем в правом столбце показаны все вызванные подфункции и их общее и суммарное время.Разбивки для этих суб-вызовов также включены и т. Д.

0 голосов
/ 25 марта 2016

Во-первых, я хочу сказать, что мне не удалось воспроизвести проблему Аскера. Профилировщик (в py2.7) определенно опускается в вызываемые функции и методы. (Документы для py3.6 выглядят одинаково, но я не тестировал на py3.) Я предполагаю, что, ограничив его 10 лучшими результатами, отсортированными по совокупному времени, первые N из них были функциями очень высокого уровня, называемыми минимальное время, и функции, вызываемые foo(), выпали из нижней части списка.

Я решил поиграть с большими цифрами для тестирования. Вот мой тестовый код: 

# file: mymodule.py
import math

def foo(n = 5):
    for i in xrange(1,n):
        baz(i)
        bar(i ** i)

def bar(n):
    for i in xrange(1,n):
        e  = exp200(i)
        print "len e: ", len("{}".format(e))

def exp200(n):
    result = 1
    for i in xrange(200):
        result *= n
    return result

def baz(n):
    print "{}".format(n)

И включающий файл (очень похожий на файл Аскера): 

# file: test.py

from mymodule import foo

def start():
   # ...
   foo(8)

OUTPUT_FILE = 'test.profile_info'

import pstats
import cProfile as profile

profile.run('start()', OUTPUT_FILE)
p = pstats.Stats(OUTPUT_FILE)
print "name: "
print p.sort_stats('name')
print "all stats: "
p.print_stats()
print "cumulative (top 10): "
p.sort_stats('cumulative').print_stats(10)
print "time (top 10): "
p.sort_stats('time').print_stats(10)

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

Вот часть результатов, с которой работал Аскер (cumulative -сортированный): 

cumulative (top 10):
Thu Mar 24 21:26:32 2016    test.profile_info

         2620840 function calls in 76.039 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   76.039   76.039 <string>:1(<module>)
        1    0.000    0.000   76.039   76.039 test.py:5(start)
        1    0.000    0.000   76.039   76.039 /Users/jhazen/mymodule.py:4(foo)
        7   10.784    1.541   76.039   10.863 /Users/jhazen/mymodule.py:10(bar)
   873605   49.503    0.000   49.503    0.000 /Users/jhazen/mymodule.py:15(exp200)
   873612   15.634    0.000   15.634    0.000 {method 'format' of 'str' objects}
   873605    0.118    0.000    0.118    0.000 {len}
        7    0.000    0.000    0.000    0.000 /Users/jhazen/mymodule.py:21(baz)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Посмотрите, как три верхние функции на этом экране вызывались только один раз. Давайте посмотрим на отсортированный time вид: 

time (top 10):
Thu Mar 24 21:26:32 2016    test.profile_info

         2620840 function calls in 76.039 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   873605   49.503    0.000   49.503    0.000 /Users/jhazen/mymodule.py:15(exp200)
   873612   15.634    0.000   15.634    0.000 {method 'format' of 'str' objects}
        7   10.784    1.541   76.039   10.863 /Users/jhazen/mymodule.py:10(bar)
   873605    0.118    0.000    0.118    0.000 {len}
        7    0.000    0.000    0.000    0.000 /Users/jhazen/mymodule.py:21(baz)
        1    0.000    0.000   76.039   76.039 /Users/jhazen/mymodule.py:4(foo)
        1    0.000    0.000   76.039   76.039 test.py:5(start)
        1    0.000    0.000   76.039   76.039 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Теперь запись номер один имеет смысл. Очевидно, что повышение чего-либо до 200-й степени путем многократного умножения является «наивной» стратегией. Давайте заменим это: 

def exp200(n):
    return n ** 200

И результаты: 

time (top 10):
Thu Mar 24 21:32:18 2016    test.profile_info

         2620840 function calls in 30.646 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   873612   15.722    0.000   15.722    0.000 {method 'format' of 'str' objects}
        7    9.760    1.394   30.646    4.378 /Users/jhazen/mymodule.py:10(bar)
   873605    5.056    0.000    5.056    0.000 /Users/jhazen/mymodule.py:15(exp200)
   873605    0.108    0.000    0.108    0.000 {len}
        7    0.000    0.000    0.000    0.000 /Users/jhazen/mymodule.py:18(baz)
        1    0.000    0.000   30.646   30.646 /Users/jhazen/mymodule.py:4(foo)
        1    0.000    0.000   30.646   30.646 test.py:5(start)
        1    0.000    0.000   30.646   30.646 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Это хорошее улучшение во времени. Теперь str.format() наш худший преступник. Я добавил строку в bar(), чтобы вывести длину числа, потому что моя первая попытка (просто вычислить число и ничего не делать с ним) была оптимизирована, и моя попытка избежать этого (печать числа, которое стало действительно большим очень быстро) казалось, что это может блокировать ввод / вывод, поэтому я пошел на компромисс при печати длины числа. Эй, это журнал базы-10. Давайте попробуем это: 

def bar(n):
    for i in xrange(1,n):
        e  = exp200(i)
        print "log e: ", math.log10(e)

И результаты: 

time (top 10):
Thu Mar 24 21:40:16 2016    test.profile_info

         1747235 function calls in 11.279 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        7    6.082    0.869   11.279    1.611 /Users/jhazen/mymodule.py:10(bar)
   873605    4.996    0.000    4.996    0.000 /Users/jhazen/mymodule.py:15(exp200)
   873605    0.201    0.000    0.201    0.000 {math.log10}
        7    0.000    0.000    0.000    0.000 /Users/jhazen/mymodule.py:18(baz)
        1    0.000    0.000   11.279   11.279 /Users/jhazen/mymodule.py:4(foo)
        7    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
        1    0.000    0.000   11.279   11.279 test.py:5(start)
        1    0.000    0.000   11.279   11.279 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Хм, все еще довольно много времени потрачено на bar(), даже без str.format(). Давайте избавимся от этого отпечатка: 

def bar(n):
    z = 0
    for i in xrange(1,n):
        e  = exp200(i)
        z += math.log10(e)
    return z

И результаты: 

time (top 10):
Thu Mar 24 21:45:24 2016    test.profile_info

         1747235 function calls in 5.031 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   873605    4.487    0.000    4.487    0.000 /Users/jhazen/mymodule.py:17(exp200)
        7    0.440    0.063    5.031    0.719 /Users/jhazen/mymodule.py:10(bar)
   873605    0.104    0.000    0.104    0.000 {math.log10}
        7    0.000    0.000    0.000    0.000 /Users/jhazen/mymodule.py:20(baz)
        1    0.000    0.000    5.031    5.031 /Users/jhazen/mymodule.py:4(foo)
        7    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
        1    0.000    0.000    5.031    5.031 test.py:5(start)
        1    0.000    0.000    5.031    5.031 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

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

Надеюсь, это поможет!

0 голосов
/ 10 июля 2015

Может быть, вы столкнулись с подобной проблемой, поэтому я собираюсь описать здесь мою проблему.Мой код профилирования выглядел так: 

def foobar():
    import cProfile
    pr = cProfile.Profile()
    pr.enable()
    for event in reader.events():
        baz()
        # and other things

    pr.disable()
    pr.dump_stats('result.prof')

И окончательный результат профилирования содержал только вызов events().И я потратил не так много времени, чтобы понять, что у меня было профилирование пустого цикла.Конечно, было несколько вызовов foobar() из клиентского кода, но значимые результаты профилирования были перезаписаны последним вызовом с пустым циклом.

...