고성능 파이썬(3)

CHAPTER 2. 프로파일링으로 병목 지점 찾기

 

프로파일링을 해보면 병목 지점을 찾을 수 있기 때문에 최소한의 노력으로 성능을 최대한 끌어 올릴 수 있다. 큰 수고를 들이지 않고 속도를 크게 향상시키고 자원을 적게 사용하면서, 실용적인 측면에서 코드가 충분히 빠르고 유연한 것을 목표로 삼는다. 프로파일링을 통해 최소한의 노력으로 실용적인 결정을 내릴 수 있다.

 

CPU뿐만 아니라 측정 가능한 자원은 모두 프로파일링을 할 수 있다. 이 장에서는 CPU 시간과 메모리 사용량에 대해서 살펴볼 것이다. 네트워크 대역폭과 디스크I/O 측정에서도 비슷한 기법을 적용할 수 있다.

 

2.1. 효과적으로 프로파일링 하기

프로파일링의 첫 번째 목표는 시스템의 어느 부분이 느린지, 혹은 어디서 RAM을 많이 쓰고 있는지, 디스크 I/O나 네트워크 I/O를 과도하게 발생시키는 부분이 어디인지를 확인하는 것이다. 보통 프로파일링하게 되면 평소보다 10배에서 100배까지 실행 속도가 느려지는데, 최대한 실제 상황과 유사한 조건에서 검사하고 싶다면 검사할 부분만 따로 떼어내서 검사하자. 되도록 코드를 작성할 때 모듈별로 미리 나눠놓는 편이 좋다.

 

[프로파일링 기법들]

- IPython의 %timeit 매직 명령어

- time.time()

- 데코레이터(timing decorator)를 활용한 시간 측정

- cProfile(어떤 함수가 가장 오래 걸리는지 확인할 수 있는 내장 도구)

- line_profiler(선택한 함수를 한 줄씩 프로파일링 할 수 있음)

- perf stat(CPU에서 실행된 명령의 수, CPU 캐시가 얼마나 효율적으로 활용 되었는지 알아볼 수 있음). 이 정보는 매트릭스 연산을 튜닝하는 고급 기법에 활용된다.

- heapy(파이썬 메모리에 상주하는 모든 객체를 살펴볼 수 있음, 도무지 알 수 없는 메모리 누수를 찾아야 할 때 유용하다.)

- dowser(장시간 실행되는 시스템의 경우, 실행되는 프로세스의 객체 할당 상황을 웹 브라우저에서 확인할 수 있다.

- memory_profiler(RAM 사용량이 왜 높은지 찾을 경우, RAM 사용 추이를 차트로 확인할 수 있음)

 

*어떤 방식으로 프로파일링을 하든, 잊지 말고 충분한 단위 테스트를 작성해 두자. 단위 테스트는 어이없는 실수를 줄여주고 언제든 결과를 재현할 수 있도록 해준다. 컴파일하거나 알고리즘을 다시 작성하기 전에는 꼭 프로파일링하자.

 

 

2.2. 쥘리아 집합

CPU를 많이 사용하는 흥미로운 주제다.

f(z) = z^2 + c

z의 절댓값이 2보다 작다면 이 함수를 계속 반복한다.

for z in coordinates:
  for iteration in range(maxiter):  # 최대 반복 횟수
    if abs(z) < 2.0:  # 종료 조건 검사
      z = z*z + c
    else:
      break
  # 각 z값에 대해서 반복 횟수를 기록하고 나중에 그린다.

 

2.4. 시간을 측정하는 간단한 방법 - print와 데코레이터

print 함수를 통해서 실행시간을 측정 가능

데코레이터는 단순히 print문을 대체한다.

from functools import wraps

def timefn(fn):
  @wraps(fn)  # 이 부분으로 인해 데코레이터로 넘어온 함수의 이름과 독스트링(docstring)을 호출하는 함수에서 확인 할 수 있음.
  def measure_time(*args, **kwargs):  # args: 가변 길이 인자, kwargs: 키워드 인자.
    t1 = time.time()
    result = fn(*args, **kwargs)
    t2 = time.time()
    print("@timefn: {} took {} seconds".format(fn.__name__, t2 - t1))
    return result
  return measure_time

@timefn
def calculate_z_serial_purepython(maxiter, zs, cs):
  ...

 

[timeit 모듈]

* timeit 모듈은 일시적으로 GC를 비활성화시킨다. 이로 인해 GC가 활성화되는 일반적인 상황과는 실행 속도에서 차이가 날 수 있다.(http://bit.ly/timeit_doc)

 

$ python -m timeit -n 5 -r 5 -s "import julia1"
"julia1.calc_pure_python(desired_width=1000, max_iterations=300)"

 

-s를 사용해서 그 모듈을 임포트 해야 한다.

-r 5는 반복횟수를 나타냄

-n 5는 각 검사에서의 평균을 구한다.

결과로 전체 반복 중에서 가장 나은 값을 출력한다.

 

IPython에서는 %timeit calc_pure_python(desired_width=1000, max_iterations=300)

의 형식으로 쓸 수 있다.

 

 

 

2.5. 유닉스 time 명령어를 이용한 간단한 시간 측정

$/usr/bin/time -p python julia_nopil.py

Length of x: 1000

Total elements: 1000000

calculate_z_serial_purepython took 12.7298.. seconds

real 13.46

user 13.40

sys 0.04

 

-p 옵션은 다음과 같은 세 가지 결과를 얻을 수 있다.

real 항목은 경과된 시간을 기록한다.

user 항목은 CPU가 커널 함수 외 작업을 처리하느라 소비한 시간을 기록한다.

sys 항목은 커널 함수를 수행하는 데 소비한 시간을 기록한다.

 

--verbose 플래그를 넘기면 더 자세한 결과를 확인할 수 있다.

 

이 중에서 가장 눈여겨봐야 할 항목은 'Major (requiring I/O) page faults' 항목인데, 이 항목은 운영체제가 RAM에서 필요한 데이터를 찾을 수 없어서 디스크에서 페이지를 불러 왔는지의 여부를 나타낸다. 이는 속도를 느리게 하는 원인이다.

 

2.6. cProfile 모듈 사용하기

cProfile은 표준 라이브러리에 내장된 프로파일링 도구다. cProfile은 CPython의 가상 머신 안에서 확인되는 모든 함수에 시간 측정을 위한 장치를 연결한다. 이는 큰 오버헤드를 유발하지만 그만큼 더 많은 정보를 제공한다. 때때로 이런 추가 정보로 인해 작성한 코드에 대해 놀랄만한 통찰을 얻을 수도 있다.

 

프로파일링하기 전에 프로파일링하려는 코드의 기대 속도에 대한 가설을 세우는 습관을 들이는 것이 좋다. 저자의 경우는 의심스러운 코드를 출력해서 메모하는 방식을 선호한다. 가설을 다듬다보면 무엇이 잘못되었는지 확인할 수 있고, 코딩 방식에 대한 직관을 키울 수도 있다.

* 감으로 프로파일링하는 습관은 반드시 피해야 한다. 이 방식은 십중팔구 실패한다.

 

cProfile의 -s cumulative 옵션은 각 함수에서 소비한 누적 시간순으로 정렬되어 어떤 함수가 더 느린지 쉽게 확인 할 수 있다.

$ python -m cProfile -s cumulative julia1_nopil.py

 

누적 소비 시간으로 정렬하면 실행 시간을 주로 소비하는 곳이 어딘지 쉽게 확인할 수 있다.

 

$ cProfile의 결과를 더 세밀하게 살펴보려면 통계 파일을 생성한 뒤 파이썬으로 분석할 수 있다.

$ python -m cProfile -o profile.stats julia1.py

 

다음과 같이 파이썬에서 통계 파일을 불러들이면 앞서 살펴본 출력과 같은 결과를 확인할 수 있다.

import pstats
p = pstats.Stats("profile.stats")
p.sort_stats("cumulative")
p.print_stats()
p.print_callers()  # 함수를 호출한 측의 정보를 출력. 
p.print_callees()  # 해당 함수에서 호출하는 함수 목록도 확인할 수 있다.

2.7. line_profiler로 한 줄씩 측정하기

로버트 컨(Robert Kern)의 line_profiler가 파이썬 코드에서 CPU 병목 원인을 찾아주는 가장 강력한 도구일 것이다. line_profiler는 개별 함수를 한 줄씩 프로파일링할 수 있으므로 먼저 cProfile을 사용해서 어떤 함수를 line_profiler로 자세히 살펴볼지에 대한 전체적인 방향을 정하면 된다.

 

코드를 수정해가면서 line_profiler의 결과에 버전을 기록해두면 변경 사항에 대한 성공/실패 기록을 빠르게 참고할 수 있다. 한 줄씩 코드를 수정할 때는 기억력에 의존하지 않도록 하자.

 

line_profiler를 설치하려면 pip install line_profiler를 입력하면 된다.

@profile 데코레이터는 선택한 함수를 표시하기 위해 사용한다.

* 더미(dummy) 데코레이터를 만들지 않으면 추가한 데코레이터 단위 테스트를 망가뜨릴 수 있어서 line_profiler를 사용하기 위해 코드를 변경하는 일이 약간 귀찮을 수 있다. 2.12.1절 "No-op @profile 데코레이터"를 참고하자.

 

$ python -m kernprof.py -l -v julia1_lineprofiler.py

 

느려진 원인을 확보했으면,

timeit을 이용해서 각 명령의 개별 비용을 검사해보는 편이 더 좋다.

>>> z = 0 + 0j # 이미지의 정가운데 좌표
>>> %timeit abs(z) < 2 # IPython 안에서 검사

10000000 loops, best of 3: 119 ns per loop

>>> n = 1
>>> maxiter = 300
>>> %timeit n < maxiter

10000000 loops, best of 3: 77 ns per loop

timeit을 통한 간단한 분석에 의하면 n 값을 검사하는 코드가 abs를 호출하는 코드보다 거의 두 배 빠르다.

 

다음과 같은 이유로 개선 결과를 확신할 수 있다.

- 쉽게 검증할 수 있는 가설을 세웠다.

- 그 가설을 검증할 수 있도록 코드를 수정했고, 한 번에 한 가지만 검사했다.

- 결론을 뒷받침하기에 충분한 근거를 수집했다.

 

2.8. memory_profiler로 메모리 사용량 진단하기

CPU 사용량을 측정하는 로버트 컨의 line_profiler처럼 메모리 사용량을 줄 단위로 측정해주는 memory_profiler가 있다.

자신이 작성한 코드의 메모리 사용 특성을 이해하고 나면 다음 질문에 스스로 답할 수 있다.

- 이 함수를 더 효과적으로 작동하게 고쳐서 RAM을 덜 쓸 수 있는가?

- 캐시를 두어 RAM을 조금 더 쓰는 대신 CPU 사이클을 아낄 수 있는가?

 

psutil 패키지를 설치하면 memory_profiler를 더 빠르게 실행할 수 있다.

메모리 프로파일링을 하면 코드의 실행 속도는 평소보다 10배에서 100배까지 느려진다.

보통은 line_profiler를 memory_profiler보다 더 자주 사용하게 될 것이다.

 

memory_profile은 pip install memory_profiler 명령으로 설치할 수 있다. 그리고 psutil은 pip install psutil 명령으로 설치할 수 있다.

 

메모리 할당과 관련하여 살펴볼 때는 CPU 사용량을 측정하는 것만큼 깔끔하지 않은 상황에 주의해야 한다. 일반적으로 메모리 할당은 상대적으로 비싼 작업이므로 필요한 양보다 많은 메모리를 로컬 풀에 미리 할당해두고 여유롭게 사용하는 방법이 효율적이다. 더욱이 GC는 즉각적으로 동작하지 않으므로 객체가 더 이상 유효하지 않음에도 한동안 풀에 남아있기도 한다.

 

이런 연유로, 파이썬 프로그램에서 메모리의 사용과 해제에 대해 제대로 이해하기란 쉽지 않다.

* memory_profiler는 국제전기표준회의의 MiB(메비바이트, 2^20바이트) 단위로 메모리 사용량을 측정한다.

calculate_z_serial_purepython에서 1,000,000개의 아이템을 할당했고 약 7MB의 RAM을 사용했다. 이는 output 리스트가 7MB 크기라는 뜻은 아니고 해당 프로세스가 내부적으로 리스트를 할당하는 동안 약 7MB만큼의 메모리를 더 사용한다는 뜻이다.

$ python -m memory_profiler julia1_memoryprofiler.py

 

메모리 사용량의 변화를 시각화하는 다른 방법은 시간에 따라 샘플링하고 그 결과를 그래프로 그려보는 것이다. memory_profiler에 포함된 mprof라는 유틸리티는 메모리 사용량을 샘플링한 다음, 그 샘플을 시각화해준다.

mprof run julia1_memoryprofiler.py 명령으로 생성한 것이다. 이 명령을 실행하면 먼저 통계 파일을 생성하고 mprof plot 명령으로 시각화한다. 그래프를 더 쉽게 읽으려면 time.sleep(1)을 코드에 추가하면 된다.

 

 

2.9. heapy로 힙 메모리 살펴보기

Guppy 프로젝트는 파이썬 힙 메모리에 있는 객체의 수와 크기를 살펴볼 수 있도록 heapy라는 이름의 힙 메모리 조사 도구를 제공한다. 드문 경우지만 디버깅을 하다 보면 얼마나 많은 객체가 사용 중인지, 또 적절한 타이밍에 GC가 이루어졌는지를 알아야 하는 경우가 있는데, 이 때 인터프리터 내부와 메모리에 저장된 내용을 이해하고 있다면 매우 유용하다. 찾기 힘든 메모리 누수(복잡한 시스템에서 객체에 대한 참조가 숨겨진 경우)를 찾고 있다면 heapy를 사용해서 문제의 원인을 발견할 수 있을 것이다.

 

코드가 예상한 만큼의 객체를 생성하고 있는지 살펴보고 있다면 heapy가 제공하는 결과가 놀라울지도 모른다. 이를 통해 새로운 최적화 가능성을 찾아낼 수도 있다.

heapy를 사용하려면 pip install guppy 명령으로 guppy 패키지를 설치하면 된다.

 

 

def calc_pure_python(draw_output, desired_width, max_iterations):
  ...
  while xcoord < x2:
    x.append(xcoord)
    xcoord += x_step

from guppy import hpy; hp = hpy()
print("heapy after creating y and x lists of floats")
h = hp.heap()
print(h)
print()

zs = []
cs = []
for ycoord in y:
  for xcoord in x:
    zs.append(complex(coord, ycoord))
    cs.append(complex(c_real, c_imag))
print("heapy after creating zs and cs using complex numbers")
h = hp.heap()
print(h)
print()

print("Lengh of x:", len(x))
print("Total elements:", len(zs))
start_time = time.time()
output = calculate_z_serial_purepython(max_iterations, zs, cs)
end_time = time.time()
secs = end_time - start_time
print(calculate_z_serial_purepython.__name__ + "took", secs, "seconds")

print()
print("heapy after calling calculate_z_serial_purepython")
h = hp.heap()
print(h)
print()

heapy를 사용해서 코드가 실행되는 동안 객체 개수가 변하는 과정 살펴보기

 

hpy.setrelheap() 함수는 메모리 설정에서 체크포인트를 생성하기 위해 사용한다. 이후에 호출하는 hpy.heap() 함수는 체크포인트에서 변화한 내용을 출력한다. 이렇게 하면 분석을 시작하기 이전 시점의 메모리 설정과 파이썬 내부 상태는 신경 쓰지 않아도 된다.

 

2.10. dowser로 변수 생성을 실시간으로 확인하기

로버트 브루어가 만든 dowser는 실행 중인 코드의 네임스페이스를 조작하여 CherryPy 인터페이스를 통해 웹 브라우저에서 생성하는 변수를 실시간으로 확인할 수 있다. 이 도구는 오랫동안 실행되는 프로세스를 디버깅할 때 유용하다.

 

def launch_memory_usage_server(port=8080):
  import cherrypy
  import dowser
  
  cherrypy.tree.mount(dowser.Root())
  cherrypy.config.update({
    'environment': 'embedded',
    'server.socket_port': port
  })
  
  cherrypy.engine.start()

애플리케이션에서 dowser를 실행하기 위한 함수

복잡한 계산을 시작하기 전에 cherrypy 서버를 실행하자. 계산이 끝난 뒤에 time.sleep을 추가하여 cherrypy 프로세스가 종료되지 않도록 하고 네임스페이스의 상태를 살펴보자.

 

2.11. dis 모듈로 CPython의 바이트코드 조사하기

지금까지 파이썬 코드의 CPU와 RAM 사용량을 측정하는 여러 방법을 알아봤다. 파이썬 가상 머신에서 사용하는 내부 바이트코드는 아직 살펴보지 않았는데, 밑바닥에서 벌어지는 일을 이해하면 느리게 동작하는 함수에서 벌어지는 일련의 과정을 머릿속에서 그려볼 수 있고, 언제 컴파일이 필요한지를 알 수 있다. 이제 바이트코드에 대해서 알아보자.

 

dis 모듈을 통해 스택 기반의 CPython 가상 머신에서 동작하는 바이트코드를 살펴볼 수 있다. dis 모듈은 기본으로 내장되어 있다.

 

import dis
import julia1_nopil

dis.dis(julia1_nopil.calculate_z_serial_purepython)

첫 번째 컬럼은 원래 소스 파일의 줄 번호를 나타낸다. 두 번째 컬럼은 >> 기호를 포함하는데, 이는 코드의 다른 지점에서 점프해오는 지점이다. 세 번째 컬럼은 연산의 주소와 그 이름이며, 네 번째 컬럼은 해당 연산에 전달하는 매개변수다. 마지막으로 다섯 번째 컬럼은 이해를 돕기 위해 원래 파이썬 코드를 같이 출력한 것이다.

 

def fn_expressive(upper = 1000000):
  total = 0
  for n in range(upper):
    total += n
  return total

def fn_terse(upper = 1000000):
  return sum(range(upper))

print("Functions return the same result:", fn_expressive() == fn_terse())

%timeit fn_expressive()
10 loops, best of 3: 42 ms per loop

%timeit fn_terse()
100 loops, best of 3: 12.3 ms per loop

import dis
print fn_expressive.func_name
dis.dis(fn_expressive)

내장 함수를 사용한 버전은 6회의 연산을 수행하지만, 직접 작성한 경우 17회의 연산을 수행해야 한다.

 

2.12. 최적화 중에 단위 테스트 하기

단위 테스트와 더불어 coverage.py도 함께 고려하기를 강력히 추천한다. coverage.py를 사용하면 코드의 어떤 부분이 검사되었고 검사되지 않은 부분은 어디인지 알 수 있다. 이를 통해 최적화 하려는 코드가 검사되는지를 쉽게 알 수 있어서 최적화 중에 실수를 하게 되면 빠르게 알 수 있다.

 

2.12.1. no-op @profile 데코레이터

line_profiler나 memory_profiler에서 @profile을 사용하면 단위 테스트에서 NameError예외가 발생한다. 단위 테스트 프레임워크는 @profile 데코레이터를 로컬 네임스페이스에 추가하지 않기 때문인데, ㄷ아무것도 하지 않는 no-op 데코레이터를 이용하면 이 문제를 피할 수 있다. 검사하려는 코드 블록에 추가하고, 검사가 끝나면 제거하면 된다.

 

no-op 데코레이터를 이용하면 검사하려는 코드를 변경하지 않고 테스트를 실행할 수 있다. 즉, 프로파일링을 통한 최적화 작업 중에도 테스트를 돌려볼 수 있기 때문에 잘못된 최적화에 빠지는 일을 방지할 수 있다.

 

# ex.py
import unittest

@profile
def some_fn(nbr):
  return nbr*2

class TestCase(unittest.TestCase):
  def test(self):
    result = some_fn(2)
    self.assertEquals(result, 4)

@profile을 사용할 간단한 함수

$ nosetests ex.py

nosetests를 실행하면 NameError가 발생한다.

 

해결책은 ex.py의 첫 부분에 no-op 데코레이터를 추가하는 것이다.(프로파일링이 끝나고 제거하면 된다.)

 

# line_profile용
if '__builtin__' not in dir() or not hasattr(__builtin__, 'profile'):
  def profile(func):
    def inner(*args, **kwargs):
      return func(*args, **kwargs)
    return inner

__builtin__ 테스트는 nosetests 유무를 위한 것이고 hasattr 테스트는 네임스페이스에 profile이 추가되었는지 검사한다. 이제 nosetests를 실행해보면 정상적으로 작동한다.

 

# memory_profiler용
if 'profile' not in dir():
  def profile(func):
    def inner(*args, **kwargs)
  return inner

 

몇 분을 아끼려고 이 과정을 건너뛸 수도 있지만, 몇 시간을 고생해서 한 최적화가 결국은 잘못된 코드인 실수를 겪고 나면 항상 이렇게 하게 될 것이다.

 

2.13. 성공적인 코드 프로파일링 전략

전체 코드에서 검사하려는 일부 코드만 분리하면 코드를 더 잘 이해하게 될 가능성이 높다. 그리고 단위 테스트를 통해 코드의 정확함을 유지하면서 현실적인 데이터를 바탕으로 찾고자 하는 비효율성을 실험해볼 수 있다.

 

BIOS에서 제공하는 가속 기능은 결과를 헷갈리게 할 수 있으니 끄도록 하자. 저자의 노트북에 탑재된 인텔 터보부스트 기능은 CPU 온도가 낮으면 일시적으로 CPU의 속도를 정상 이상으로 끌어올린다. 즉 같은 코드라도 CPU 온도가 낮을 때 실행하면 더 빠르게 작동한다는 의미다. 운영체제에서 클럭 속도를 제어하기도 한다.

- BIOS에서 터보부스트 기능을 끈다.

- 운영체제의 스피드스텝 기능을 끈다(BIOS 설정에 있음)

- 배터리가 아닌 일반 전원을 사용하자.

- 실험할 때는 백업이나 드롭박스 같은 백그라운드 작업을 중지하자.

- 안정적인 결과를 얻도록 여러 번 실험하자.

- 유닉스에서는 가능하다면 런 레벨 1로 부팅해서 다른 작업이 실행되지 않도록 하자.

- 결과 검증을 위해서는 재부팅 후에 한 번 더 실험해 보자.

 

웹 서버는 dowser와 dozer로 조사하자. 이 도구를 사용해서 실시간으로 네임스페이스상의 객체를 시각화할 수 있다.

출력이 많은 복잡한 프로그램은 단위 테스트가 어려울 수 있다. 이런 경우 출력 결과를 텍스트 파일로 저장해서 diff를 돌려보거나 객체를 pickle로 저장하자. 수치 최적화 문제의 경우, 저자는 수를 텍스트 파일로 저장한 다음 diff를 사용해서 잘못된 반올림을 쉽게 찾아낸다.

 

 

요약

1. CPU 실행속도 측정을 위해서는 cProfile -> line_profiler -> %timeit 순으로 실행하며 수정한다.

2. 단위 테스트는 nosetests, unittest, coverage.py를 사용한다.

3. dis 모듈을 이용하면 디스어셈블된 코드를 볼 수 있다.