python:profiling

[출처 : http://wiki.dgoon.net/doku.php?id=python:profiling]

Python

파이썬용 프로파일링 툴 중 디군이 써본것들 모음. 나중에 까먹으면 뒤적이면 기억을 되살릴 정도로만 정리한다. 모두 DeterministicProfiling 툴이다.

• profile
• cProfile
• yappi

profile, cProfile 은 언젠가부터 파이썬 빌트인이 되었다. yappi 는 여기에서 구할 수 있다.

Profile

순수 파이썬으로 만들어진 프로파일러다. 기본적으로,

1. import profile
2. 프로파일 데이터를 얻을 코드의 실행조각 준비
3. profile.run 함수에 준비된 코드조각과 결과 데이터가 쓰일 파일 이름을 넘김
4. 파일 이름을 넘겼다면, 해당 이름을 가진 파일에 프로파일 데이터가 쓰이고,
5. 그렇지 않은 경우 stdout 으로 결과가 나온다

How to write code

예를 들어 간단히 숫자를 더하는 함수를 분석하고 싶다면,

def test(n=100):
    return sum(x for x in xrange(n))
import profile
profile.run('print(test())')
profile.run('print(test(20))')

이런 식으로 사용할 수 있으며, 결과 파일을 지정해주지 않았으니 실행하면 stdout 으로 결과를 볼 수 있다. 실행 결과는 아래와 같다.

4950
         106 function calls in 0.010 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.010    0.010    0.010    0.010 :0(setprofile)
        1    0.000    0.000    0.000    0.000 :0(sum)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.010    0.010 profile:0(print(test()))
        0    0.000             0.000          profile:0(profiler)
        1    0.000    0.000    0.000    0.000 t.py:1(test)
      101    0.000    0.000    0.000    0.000 t.py:2(<genexpr>)


190
         26 function calls in 0.000 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        1    0.000    0.000    0.000    0.000 :0(sum)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 profile:0(print(test(20)))
        0    0.000             0.000          profile:0(profiler)
        1    0.000    0.000    0.000    0.000 t.py:1(test)
       21    0.000    0.000    0.000    0.000 t.py:2(<genexpr>)

How to read stat

일단, docs.python.org 에 있는 내용을 그냥 가져오겠다. 왼쪽부터 순서대로 ncalls/tottime/percall/cumtime/percall 가 있다.

• ncalls: 호출 횟수
• tottime: 해당 함수에서 사용한 시간 - 내부에서 부른 다른 함수 호출 시간은 제외
• percall: tottime / ncalls
• cumtime: 함수 진입부터 나갈 때 까지의 시간 - 다른 함수 호출 시간도 포함
• percall: cumtime / primitive calls

cumtime 의 경우 재귀함수에 대해서도 동작하는데 이 때문에 primitive calls 가 따로 존재한다. ncalls 에 숫자가 두개, a/b 처럼 나오는 경우 a가 actual calls, b가 primitive calls 다. primitive calls는 재귀 횟수를 무시한 호출횟수다. 예를 들어서,

def t(n=100):
    if n == 0:
        return n
    return n+t(n-1)
import profile
profile.run('print(t())')

이런 경우에는

5050
         104 function calls (4 primitive calls) in 0.010 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.010    0.010    0.010    0.010 :0(setprofile)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.010    0.010 profile:0(print(t()))
        0    0.000             0.000          profile:0(profiler)
    101/1    0.000    0.000    0.000    0.000 test_recursive.py:1(t)
    

이렇게 actual calls=101, primitive calls=1 이라는 결과가 나온다.

Command line

이렇게 꼭 코드 조각을 넣어야 하는게 귀찮을 수도 있다. 쓰던 코드를 고치지 않고 바로 프로파일링을 해보고 싶은데 말이지 … 그렇다면 그냥 커맨드라인에서 프로파일 옵션을 줄 수도 있다.test.py 라는 파일을 프로파일링 하고 싶다고 하자. 그러면,

python -m profile test.py

혹은, 결과를 파일로 얻고 싶다면

python -m profile -o test.prof test.py

이렇게 실행할 수 있다.

Analyze profiling data file

profile.run 혹은 커맨드라인 명령을 통하여 프로파일링 데이터가 저장된 파일을 얻었다면 pstat 모듈로 이를 읽을 수 있다.

1. import pstats
2. pstats.Stat 클래스 생성자에 파일 패스를 넘겨 스탯 객체를 얻는다
3. 스탯 객체의 sort_stats, print_stats 등을 사용해서 스탯을 본다.

위에서 test.prof 를 만들었으니 이를 예로 들어보면 아래와 같이 볼 수 있다. 정렬에 대한 좀 더 자세한 설명은 여기서 보자.

import pstats
stat = pstats.Stats('test.prof')
stat.sort_stats('cumulative').print_stats(30)

Tue May 11 18:05:24 2010    test.prof

         131 function calls in 0.010 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.010    0.010 profile:0(execfile('test.py'))
        1    0.000    0.000    0.010    0.010 test.py:1(<module>)
        1    0.000    0.000    0.010    0.010 :0(execfile)
      122    0.010    0.000    0.010    0.000 test.py:2(<genexpr>)
        1    0.000    0.000    0.010    0.010 <string>:1(<module>)
        2    0.000    0.000    0.010    0.005 test.py:1(test)
        2    0.000    0.000    0.010    0.005 :0(sum)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
        0    0.000             0.000          profile:0(profiler)

cProfile

cProfile은 profile과 거의 동일한 인터페이스를 가진 C-binding 이다. 위의 profile 에 대한 내용에서 profile→cProfile 로 바꾸면 모두 동작한다. 프로파일러의 몇몇 확장에서 차이를 보일 수 있으나, 그 부분은 여기서 다루지는 않는다. cProfile 쪽이 오버헤드가 더 작다고 한다.

Yappi

Yet Another Python Profiler

profile/cProfile은 스레드를 사용하는 프로그램은 기본적인 사용법만으로는 프로파일링 데이터를 얻어낼 수 없고, 오직 메인 스레드만을 프로파일링 하게 된다. 멀티스레드 프로그램을 프로파일링 하기 위해서는,

• 각 스레드로부터 각각 프로파일링 데이터를 얻어낸 후 이를 합친다
• threading.setprofile 에 적절한 프로파일링 함수(혹은 함수 객체)를 만들어 넘긴다

정도의 작업이 필요하다. 이게 귀찮으면 나름 간단한 인터페이스로 무장한 yappi 를 사용해 볼 수 있다.

Concept

• yappi는 파이썬 인터프리터당 하나씩의 객체만 있다. 싱글톤이라고 봐도 무난할 듯 싶다.
• 프로파일링 하고 싶은 부분이 시작되기 전에 yappi.start, 마치고 나서 yappi.stop 을 불러주면 된다.
• start-stop 은 짝만 맞으면 여러번 할 수 있으므로 프로파일링 범위를 조절할 수 있다.
• yappi.get_stats 를 부르면 스탯이 나온다. 숫자같은건 없으므로 그냥 '\n'.join(yappi.get_stats()) 를 찍어놓고 읽는게 편하다.
• profile/cProfile 처럼 actual calls/primitive calls 구분은 안해준다

Install

그냥 소스코드를 받아서 python setup.py install 을 실행하면 된다. 디군은 계정 로컬로 설치하기 위해 –prefix 옵션을 주었다.

svn checkout http://yappi.googlecode.com/svn/trunk/ yappi-read-only
cd yappi-read-only
python setup.py install --prefix=~/works

물론 이렇게 로컬에 설치하는 경우에는 prefix/lib/python2.x/site-packages 를 PYTHONPATH 에 잡아주어야 한다.

How to write code

긴 설명보다 그냥 샘플 코드가 나을 듯.

import yappi
from threading import Thread

yappi.start()
def test(n=100):
    return sum(x for x in xrange(n))
test(10000)
yappi.stop()

def recursive(n=100):
    if n == 0:
        return n
    return n+recursive(n-1)
yappi.start()
recursive(100)
yappi.stop()

yappi.start()
class TestThread(Thread):
    def __init__(self, n=100):
        Thread.__init__(self)
        self.n = n

    def run(self):
        self.output = sum(x for x in xrange(self.n))

t_list = []
for t_n in xrange(10):
    t = TestThread(100000)
    t_list.append(t)
    t.start()

for t in t_list:
    t.join()
    print t.output
yappi.stop()

print('\n'.join(yappi.get_stats()))

4999950000
4999950000
4999950000
4999950000
4999950000
4999950000
4999950000
4999950000
4999950000
4999950000




name                                 #n       tsub       ttot       tavg
test_yappi.py.<genexpr>:25           1000010  28.059563  28.059563  0.000028   
test_yappi.py.<genexpr>:6            10001    0.036889   0.036889   0.000004   
test_yappi.py.recursive:10           101      0.000000   0.000000   0.000000   
..lib/python2.6/threading.py._note:6 58       0.000134   0.000134   0.000002   
../python2.6/threading.py.__init__:5 40       0.000132   0.000132   0.000003   
..ython2.6/threading.py._is_owned:22 24       0.317279   0.317395   0.013225   
..ython2.6/threading.py.Condition:17 20       0.000141   0.000587   0.000029   
..n2.6/threading.py.currentThread:80 20       0.000109   0.000148   0.000007   
..python2.6/threading.py.__init__:18 20       0.000389   0.000446   0.000022   
..ib/python2.6/threading.py.isSet:37 20       0.000043   0.000043   0.000002   
..n2.6/threading.py._release_save:21 14       0.000061   0.000093   0.000007   
..6/threading.py._acquire_restore:21 14       0.000075   0.000149   0.000011   
..lib/python2.6/threading.py.wait:23 14       0.000440   4.492487   0.320892   
..ib/python2.6/threading.py.start:46 10       0.000227   1.464204   0.146420   
..python2.6/threading.py._newname:40 10       0.000128   0.000128   0.000013   
test_yappi.py.run:24                 10       0.000034   1.980854   0.198085   
..ython2.6/threading.py.notifyAll:29 10       0.000099   0.000434   0.000043   
..python2.6/threading.py.__init__:36 10       0.000116   0.000540   0.000054   
..b/python2.6/threading.py.daemon:68 10       0.000028   0.000028   0.000003   
..ib/python2.6/threading.py.Event:35 10       0.000062   0.000602   0.000060   
..lib/python2.6/threading.py.wait:39 10       0.000207   1.463267   0.146327   
..hon2.6/threading.py._set_daemon:44 10       0.000089   0.000193   0.000019   
..lib/python2.6/threading.py.join:62 10       0.000234   3.029895   0.302989   
..b/python2.6/threading.py.notify:27 10       0.000137   0.000306   0.000031   
..b/python2.6/threading.py.__stop:58 10       0.000172   0.000670   0.000067   
..python2.6/threading.py.__init__:42 10       0.000295   0.001501   0.000150   
test_yappi.py.__init__:20            10       0.000095   0.001596   0.000160   
..n2.6/dist-packages/yappi.py.stop:4 3        0.000000   0.000000   0.000000   
..ython2.6/threading.py.setprofile:8 3        0.000008   0.000008   0.000003   
test_yappi.py.test:5                 1        0.000013   0.066473   0.066473   
test_yappi.py.TestThread:19          1        0.000004   0.000004   0.000004   


name           tid    fname                                scnt     ttot
_MainThread    1404.. ..ython2.6/threading.py.setprofile:8 18       15.052343  
TestThread     1404.. ..lib/python2.6/threading.py._note:6 41       3.035096   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 44       3.392308   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 39       2.893798   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 45       2.980898   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 32       2.609834   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 44       3.146486   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 33       2.057063   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 28       3.148883   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 38       3.028107   
TestThread     1404.. ..lib/python2.6/threading.py._note:6 42       3.748974   


status     tstart                     fcnt     tcnt     mem(bytes)
stopped    Tue May 11 19:23:22 2010   81       11       105408   

real	0m4.635s
user	0m0.720s
sys	0m3.150s

Profile/cProfile on Multithread program

• 위에서 언급한 스레드마다 profile 을 따로 뽑아보는 접근을 해보자
• profile.run, cProfile.run 대신 profile.runctx, cProfile.runctx 를 사용할 수 있다
• ctx버전은 실행할 코드조각에 환경 - globasl(), locals() - 을 추가로 넘긴다

import cProfile
class ThreadToProfile(threading.Thread):
    def __init__(self):
        threading.Thread.__init__(self)
        
    def run_profile(self):
        """ DO WHATEVER YOU WANT """
        pass
        
    def run(self):
        cProfile.run("self.run_profile()", globals(), locals())

이 경우 stdout 으로 각 스레드의 프로파일 결과가 나오게 된다. 이를 합치기 위해서는 각각 다른 이름의 파일(이름이 같으면 broken pipe, 혹은 덮어쓰기)로 만들어서 pstats 으로 하나를 열고, 나머지 파일들을 Stat.add 메소드로 더하면 된다.

Links

• http://docs.python.org/library/profile.html
• http://code.google.com/p/yappi/