[PYTHON] cProfile에서 의미있는 결과를 얻는 파이썬

cProfile에서 의미있는 결과를 얻는 파이썬

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의 결과에서 그룹화 된 모든 시간을 주석 라인은 어떤 의미도 없거나 최소한 실제로 소비하고있는 것에 어떤 빛도 내지 않습니다.

편집 : 동일한 동작을 보여주기 위해 위의 경우와 유사한 최소 작업 예제를 구축했습니다 :

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을 잘못 사용하고 있습니까?

해결법

1. ==============================

   1.덧글에서 언급했듯이, cProfile이 외부에서 작동하도록 할 수없는 경우에는 종종 내부적으로 사용할 수 있습니다. 그리 어렵지 않습니다.

   덧글에서 언급했듯이, cProfile이 외부에서 작동하도록 할 수없는 경우에는 종종 내부적으로 사용할 수 있습니다. 그리 어렵지 않습니다.

   예를 들어, Python 2.7에서 -m cProfile을 사용하여 실행하면 효과적으로 결과를 얻습니다. 그러나 내가 수동으로 당신의 예제 프로그램을 준비 할 때 :

   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 = cProfile.Profile()
   pr.enable()
   import mwe
   pr.disable()
   pr.print_stats(sort='time')
   

   심지어 그것이 항상 작동하지는 않습니다. 예를 들어 프로그램에서 exit ()를 호출하면 try : / finally : 래퍼 및 / 또는 atexit를 사용해야합니다. 그리고 그것을 os._exit () 또는 segfaults라고 부르면 아마 완전히 엉성해질 것입니다. 하지만 그렇게 흔한 것은 아닙니다.

   그러나, 내가 나중에 발견 한 것 : 모든 코드를 전역 범위 밖으로 이동하면 최소한이 경우에는 -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 (다음)

   왜 이것이 두 배나 느리게 만들었는지 전혀 알지 못합니다. 아니면 캐시 효과 일 수도 있습니다. 마지막으로 실행 한 지 몇 분이 지났으며 그 사이에 많은 웹 검색을 수행했습니다. 그러나 중요한 것은 아닙니다. 중요한 것은 합리적인 곳으로 대부분의 시간을 청구하는 것입니다.

   그러나 바깥 쪽 루프를 전역 수준으로 이동하고 몸체 만 함수로 변경하면 대부분의 시간이 다시 사라집니다.

   마지막 대안으로 제시하지 않는 또 다른 대안은 ...

   프로필을 cProfile 대신 사용하면 내부 및 외부에서 모두 작동하여 올바른 통화 시간을 충전 할 수 있습니다. 그러나 이러한 호출은 약 5 배 느립니다. 또한 10 초의 일정한 오버 헤드가있는 것으로 보입니다 (외부에서 사용되는 경우 1 행에있는 것이면 내부적으로 사용하는 경우 프로필 가져 오기가 청구됩니다). 그래서 split이 4 초를 기다리는 대신에 2.326 / 3.352를하는 대신에 내 시간의 70 %를 사용한다는 것을 알기 위해서 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을 사용하면 정확한 결과를 얻는 것으로 보입니다. 이것은 순수 Python 코드가 빠르기 때문에 PyPy의 cProfile이 프로필 위에 가짜임을 의미 할 수 있습니다.

   어쨌든 누군가가 - m cProfile이 작동하지 않는 이유를 알아 내거나 설명 할 수 있다면 좋을 것입니다. 그러나 그렇지 않은 경우에는 대개 아주 좋은 해결 방법입니다.

from https://stackoverflow.com/questions/21274898/python-getting-meaningful-results-from-cprofile by cc-by-sa and MIT license