더 많은 함수를보고하기 위해 파이썬에서 cProfiler의 깊이를 늘리시겠습니까?

Question

다른 함수를 호출하는 함수를 프로파일 링하려고합니다.

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는에 내려 brekaing의, 인 MyModule의 ") (foo는"함수에서 소비 된 말한다 것을 알게 다음과 같이 나는 프로파일 러를 호출 내가보고 싶은 것. 프로파일 러가 이러한 기능의 성능을보고하게하려면 어떻게해야합니까?

감사합니다.

Answer 1

어쩌면 비슷한 문제에 직면했을 수 있으므로 여기에서 내 문제를 설명하려고합니다. 내 프로파일 링 코드는 다음과 같이 보았다 :

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()이 한 번 이상 호출되었지만 마지막 루프가 빈 루프를 사용하여 의미있는 프로파일 링 결과를 덮어 썼습니다.

Answer 2

p.print_callees()을 사용하면 메소드 호출을 계층 적으로 분석 할 수 있습니다. 결과는 아주 자명합니다. 왼쪽 열에는 관심있는 기능을 찾을 수 있습니다. foo(), 그 다음 오른쪽 열로 이동하면 모든 하위 기능과 범위 및 합계 및 누적 시간이 표시됩니다. 이 하위 호출에 대한 세부 사항도 포함되어 있습니다.

Answer 3

먼저 Asker의 문제를 재현 할 수 없었습니다. 프로파일 러 (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으로 정렬 된보기를 추가했습니다.이보기는 "excluding time made in calls to sub-functions"함수에 소요 된 총 시간입니다. 이 뷰는 실제 작업을 수행하는 기능을 선호하는 경향이 있고 최적화가 필요할 수 있으므로 훨씬 더 유용하다고 생각합니다.

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} 

이 화면에서 상위 3 함수를 한 번만 호출했다 방법 :

다음은 아스카가 (-sorted cumulative)에서 일했다는 결과의 일부입니다. 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} 

이제는 1 번 항목이 적합합니다. 분명히 곱셈을 반복함으로써 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()이라는 줄을 추가했습니다. 숫자를 계산하고 아무 것도하지 않으면 서 첫 번째 시도가 최적화되지 않았고, 그것을 피하려고 시도했기 때문에 (숫자를 인쇄하는 것은 정말 빨랐습니다.)는 I/O에서 차단 될 수있는 것처럼 보였으므로 숫자의 길이를 인쇄하는 데 문제가 발생했습니다. 이봐, 저기베이스 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} 

흠, 심지어는 str.format()없이 bar()에서 보낸 시간의 여전히 상당량.

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} 

지금이 가장 바쁜 기능을 실제 작업을한다하고있는 물건처럼 보이는, 그래서 우리가 최적화를 마쳤 생각 :

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

그리고 결과를 :의 그 인쇄를 제거하자.

희망 하시겠습니까?