🔊 해당 포스팅은 고성능 파이썬 2판 책 서적을 읽고 개인적인 학습 목적 하에 작성된 글입니다. 포스팅에서 사용되는 자료들은 책의 내용을 참고하되 본인이 직접 재구성한 자료임을 알립니다.
이번 포스팅에서는 프로파일링을 통해 파이썬 코드의 병목 지점을 찾아보는 방법들에 대해서 배워본다. 프로파일링의 목표이자 효과는 코드의 병목 지점을 찾아 최소한의 노력으로 코드의 성능을 최대한 끌어올리는 것이다. 프로파일링 대상으로는 CPU 뿐만 아니라 측정 가능한 모든 자원이 된다. 메모리 사용량이나 네트워크 대역폭, 디스크 I/O 측정도 가능하다. 다시 말해, 시스템의 어느 부분이 느린지, 어디서 RAM을 많이 쓰는지, 디스크 I/O나 네트워크 I/O를 과도하게 발생시키는 부분이 어딘지를 확인할 수 있다.
기존 코드나 알고리즘을 수정했을 때 유닛 테스트를 작성하고 프로파일링도 같이 하는 습관을 들이는 것을 책의 저자는 권장한다. 단, 테스트할 부분은 따로 떼어네서 별도로 프로파일링을 진행하자. 그러기 위해서는 코드를 작성할 때 모듈 별로 미리 나누어 놓는 것이 편리하다. 그러면 이렇게 프로파일링하는 방법으로 파이썬에서는 어떤 것들이 있을까? 그 중에서 가장 기본적인 방법은 IPython의 %timeit 매직 명령어와 time 라이브러리의 time.time() 함수, 그리고 데코레이터를 이용하는 방법이다.
1. 기본 프로파일링 도구 : timeit, time 라이브러리, 데코레이터
도구들에 알아보기에 앞서, 프로파일링할 대상의 코드가 필요하다. 책에서는 자그마한 챕터로 별도로 하나 떼어서 프로파일링 대상 코드를 설명하지만, 본 포스팅에서는 코드 자체만 공유하도록 하겠다. 앞으로 프로파일링 시, 해당 코드를 이용할 것이다.
x1, x2, y1, y2 = -1.8, 1.8, -1.8, 1.8
c_real, c_imag = -0.62772, -.42193
def calculate_z_serial_purepython(maxiter, zs, cs):
output = [0] * len(zs)
for i in range(len(zs)):
n = 0
z = zs[i]
c = cs[i]
while abs(z) < 2 and n < maxiter:
z = z * z + c
n += 1
output[i] = n
return output
def calc_pure_python(desired_width, max_iterations):
x_step = (x2 - x1) / desired_width
y_step = (y1 - y2) / desired_width
x, y = [], []
ycoord = y2
while ycoord > y1:
y.append(ycoord)
ycoord += y_step
xcoord = x1
while xcoord < x2:
x.append(xcoord)
xcoord += x_step
zs, cs = [], []
for ycoord in y:
for xcoord in x:
zs.append(complex(xcoord, ycoord))
cs.append(complex(c_real, c_imag))
# 시간 측정 예정
output = calculate_z_serial_purepython(max_iterations, zs, cs)
assert sum(output) == 53283802
if __name__ == "__main__":
calc_pure_python(desired_width=1000, max_iterations=500)
먼저 time 라이브러리의 time.time() 함수와 print 문을 사용해서 직관적으로 시간을 측정할 수 있다. 위 코드에서 print 가 추가된 부분만 표현했고 나머지는 생략했다.
import time
x1, x2, y1, y2 = -1.8, 1.8, -1.8, 1.8
c_real, c_imag = -0.62772, -.42193
...(생략)...
def calc_pure_python(desired_width, max_iterations):
...(생략)...
for ycoord in y:
for xcoord in x:
zs.append(complex(xcoord, ycoord))
cs.append(complex(c_real, c_imag))
print("Length 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")
assert sum(output) == 53283802
if __name__ == "__main__":
calc_pure_python(desired_width=1000, max_iterations=500)
하지만 이러한 print 구문은 직관적이기에 잠깐 찾아보기에는 좋지만 표준출력을 시킴과 동시에 코드를 금방 너저분(?)하게 만든다. 다음은 파이썬의 데코레이터를 사용하는 방법이다. 데코레이터를 사용하면 print 문을 사용할 때보다 좀 더 깔끔하다는 장점이 있다.
먼저 utils.py 라는 스크립트 파일을 하나 새롭게 생성해서 아래 내용을 추가해주자. 아래의 time_func 이라는 것이 데코레이터의 역할을 한다.
import time
from functools import wraps
def time_func(func):
@wraps(func)
def measure_time(*args, **kwargs):
t1 = time.time()
result = func(*args, **kwargs)
t2 = time.time()
print(f"@time_func decorator: {func.__name__} took {t2 - t1} seconds")
return result
return measure_time
이제 메인 스크립트에서 위 데코레이터를 임포트해서 calculate_z_serial_purepython 함수를 감싸주도록 하자.
import time
from utils import time_func
x1, x2, y1, y2 = -1.8, 1.8, -1.8, 1.8
c_real, c_imag = -0.62772, -.42193
@time_func
def calculate_z_serial_purepython(maxiter, zs, cs):
output = [0] * len(zs)
for i in range(len(zs)):
n = 0
z = zs[i]
c = cs[i]
while abs(z) < 2 and n < maxiter:
z = z * z + c
n += 1
output[i] = n
return output
def calc_pure_python(desired_width, max_iterations):
x_step = (x2 - x1) / desired_width
y_step = (y1 - y2) / desired_width
x, y = [], []
ycoord = y2
while ycoord > y1:
y.append(ycoord)
ycoord += y_step
xcoord = x1
while xcoord < x2:
x.append(xcoord)
xcoord += x_step
zs, cs = [], []
for ycoord in y:
for xcoord in x:
zs.append(complex(xcoord, ycoord))
cs.append(complex(c_real, c_imag))
print("Length 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")
assert sum(output) == 53283802
if __name__ == "__main__":
calc_pure_python(desired_width=1000, max_iterations=500)
출력이 다음과 같이 나타나는데, 데코레이터를 사용해서 측정한 시간이 매우 미세하게 더 짧음을 알 수 있다. 이는 함수 호출 순서에서 비롯된 오버헤드이며 차이는 매우 적기 때문에 코드의 성능을 좌지우지 할 정도는 되지 않는다. 단, 만약 성능을 측정하는 함수(여기에서는 calculate_z_serial_purepython 함수)를 계속 반복적으로 수백만 번까지 호출하게 된다면 데커레이터가 발생시키는 오버헤드가 성능 저하를 일으킬 가능성이 높아진다.
실제로, 프로파일링이 제공해주는 정보가 많아지면 많아질 수록 코드 실행속도를 느리게 만든다. 물론 프로파일링의 일부 정보는 매우 유용한 정보를 제공하긴 하지만 코드 실행 속도를 심하게 떨어뜨리기도 한다. 따라서 프로파일링의 수준과 코드 실행 속도 간의 trade-off 관계는 명심해야 한다. 만약 프로파일링 중인데 코드 실행 속도가 매우 느리다고 생각이 될 때 현재 진행중인 프로파일링이 제공하는 정보의 양 즉, 프로파일링 수준을 검토해보도록 하자.
마지막으로는 timeit 모듈을 사용해보자. timeit 모듈을 사용해서 CPU를 집중적으로 사용하는 함수의 실행속도를 측정할 수도 있다. time it을 사용하는 명령어 예시는 아래와 같다.
python -m timeit -n 5 -r 2 -s "import main" \
"main.calc_pure_python(desired_width=1000, max_iterations=500)"
옵션에 대한 설명은 아래와 같다.
| 옵션 | 의미 |
| -n | 그 코드를 실행하는 각 테스트 횟수(number) |
| -r | 그 코드를 실행하는 전체 테스트 횟수(repeat) |
| -v | 정보를 모두 표시하는 옵션(verbose) |
| -s | 실행하려는 함수가 모듈 안에서 정의했다면 모듈을 임포트해야 하도록 함 |
그런데 여기서 -n 과 -r 에 대한 의미가 너무 헷갈렸다. 그래서 친절한 GPT 선생에게 질문을 구했고, 아래와 같이 이해를 할 수 있었다.
예를 들어, 우리는 직접 만든 정렬 알고리즘의 성능을 테스트한다고 가정해보자. 그리고 -n 옵션을 100으로, -r 옵션을 5로 주었다. 이 때, -n 이 의미하는 바는 정렬 알고리즘을 테스트 할 때, 서로 다른 입력의 데이터를 테스트하는 횟수이다. 다시 말해, 길이가 서로 다른 입력 데이터 100개를 넣어 정렬 알고리즘의 성능을 테스트한다. 이 때의 100개가 바로 n 옵션의 값이 된다. 그래서 위에서 설명할 때 '각 테스트' 의 횟수라고 정의했다.
그러면 -r은 무엇일까? 이 100번의 테스트를 몇 번 반복할지를 의미한다. 즉, 서로 다른 입력 100개를 정렬알고리즘에 넣은 후의 평균적인 성능이 얼마나 편차가 있는지 측정하기 위해 5번(r번) 측정하는 것이다.
참고로 timeit 모듈을 일시적으로 파이썬의 GC를 비활성화한다. 이 때문에 GC가 활성화되는 일반적인 상황과는 속도 면에서 차이가 날 수 있음을 알아두도록 하자.
2. 유닉스 time 명령어 사용하기
또 다른 프로파일링 방법으로 언어에 상관없이 Unix 계열의 OS에서는 time 이라는 명령어를 사용해서 코드의 실행 시간을 측정할 수 있다. 참고로 리눅스의 경우, time 대신 /usr/bin/time 이라고 명령어를 명시함으로써 반드시 시스템의 time 명령어를 사용해야만 한다. 만약 time --verbose 명령어를 입력했을 때, --verbose를 찾을 수 없다는 에러가 발생하면 시스템 명령어가 아닌 셸에 포함된 time 명령어를 실행한 것이다.
하지만 Mac에서는 시스템 time 명령어의 --verbose 옵션을 찾을 수 없기 때문에 한 가지 방법으로는 gnu-time 을 설치하면 된다. 설치 방법은 stackoverflow를 참고하자. 먼저 아래처럼 -p 옵션을 주어 코드를 실행해보자.
/usr/bin/time -p python main.py
결과에 총 3가지 항목이 나오는데, 각 의미하는 바는 다음과 같으며 단위는 모두 초(seconds)이다.
- real : 실행 경과 시간을 기록
- user : CPU가 커널 함수 외 작업을 처리하느라 소비한 시간을 기록
- sys : CPU가 커널 함수를 수행하는 데 소비한 시간을 기록
user, sys 항목을 봄으로써 CPU에서 시간을 어떻게 사용했는지 확인할 수 있다. real 항목의 시간과 user, sys 항목의 시간의 합을 뺀 시간(real - (user + sys))은 I/O를 기다리는 데 사용한 시간의 총량을 의미한다. 즉, 정확한 시간을 측정하는 데 방해되는 다른 작업들이 실행 중임을 의미하기도 한다.
위 자료를 예시로 들어보자. real는 5.51초, user는 5.27초, sys는 0.03초다. user 과 sys를 합한 초는 5.30초이고, real 에서 5.30초를 빼면 0.21초이다. 바로 이 0.21초가 I/O를 기다리는 데 사용한 시간의 총량을 의미한다.
보통 이 time 명령어를 사용하는 시간 측정은 보통 실행 시간이 짧은 코드를 측정하는 데 유용하다. 실행 시간이 짧은 코드는 초기 구동 시간이 전체 시간에서 차지하는 비중이 높기 때문에 코드를 시작하기 까지 걸리게 되는 시간을 파악하는 데 유용하다.
추가적으로, time 명령어에서 --verbose 옵션을 주면 좀 더 상세한 내용을 볼 수 있다. 필자는 Mac OS라서 gnu-time 패키지의 gtime 명령어를 이용했다.
여러가지 항목이 있지만 눈여겨 보아야할 항목은 빨간색 네모칸의 "Major (requiring I/O) page faults" 항목이다. 해당 부분은 코드를 실행했을 때, OS가 필요한 데이터를 RAM으로부터 찾을 수 없어서 디스크 메모리에서 페이지를 불러왔는지 여부를 의미한다. 이전 포스팅에서 배웠다시피 데이터를 읽어들이고 쓰는 속도는 RAM보다 디스크(HDD, SSD)에서 훨씬 느리기 때문에 자연스레 속도를 느리게 하는 원인이 된다.
위 출력 화면을 보면 숫자가 21번이라고 적혀있다. 이는 곧 해당 코드가 실행되는동안 21번의 주요 페이지 폴트가 발생했다는 것을 의미한다. 즉, 21번 동안 디스크 I/O가 발생했고, 이는 결국 속도 저하의 원인이 될 가능성이 높음을 의미한다.
3. cProfile 모듈 사용하기
이번에는 표준 라이브러리에 내장된 프로파일링 도구 중 하나인 cProfile을 이용해보자. cProfile은 CPython의 가상 머신 안에서 확인되는 모든 함수에 시간을 측정한다. 모든 함수에 시간을 측정하기 때문에 오버헤드 즉, 프로파일링을 수행하면서 발생하는 부가 비용이 크지만 제공되는 정보는 매우 풍부하다. 함수의 라인 바이 라인으로 걸린 시간을 보여주지는 않지만 프로파일링 초반에 어떤 함수 또는 소스코드의 병목 지점이 어디인지 편리하고 빠르게 찾을 수 있도록 해준다. 주로 cProfile로 개괄적인 프로파일링을 진행하고, 추후에 배울 line_profiler 같은 라인 바이 라인으로 정보를 제공해주는 디테일한 프로파일링을 진행한다.
사실 원래 cProfile이 등장하기 전 profile이라는 순수 파이썬 기반의 프로파일링 도구가 존재했다. 하지만 순수 파이썬 기반이기 때문에 느렸다. 이를 극복하기 위해 profile과 인터페이스를 같게하되 속도를 빠르게 함으로써 C로 작성했고, 이것이 바로 cProfile이다.
그러면 위에서 성능을 측정한 스크립트를 사용하되 이번엔 cProfile로 시간을 측정해보자. 참고로 -s cumulative 옵션을 주면 각 함수에서 소비한 누적 시간을 내림차순으로 정렬해서 보여준다. 다른 옵션을 살펴보려면 python -m cProfile --help 명령어로 살펴볼 수 있다.
python -m cProfile -s cumulative main.py
그러면 프로파일링 결과를 살펴보고, 하나씩 해석해보자.
우선, 화면의 가장 윗줄을 살펴보자. cProfile은 실행한 코드 블록 중 실행 시간이 가장 오래 걸렸던 함수가 무엇이고, 그 시간이 얼마인지 출력해준다. 위에서는 'calculate_z_serial_purepython' 이라는 이름의 함수가 약 8.1495초 걸렸음을 보여준다. 그리고 바로 그 밑에 줄에 실행한 코드 블록 내에서 함수를 호출한 총 횟수인 56,285,817을 출력하고 프로파일링 하는 데 총 걸린 시간인 8.466초를 출력해준다. 단, 이 8.466초에는 cProfile 프로파일링을 실행하는 데 발생한 오버헤드 시간 비용까지 포함한 시간을 의미한다. 그런데 우리가 앞서서 timeit 모듈 사용했을 때, 해당 함수의 걸린 시간이 대략 5.51초가 걸렸음을 확인했다. 고로, 8.46초에서 5.51초를 뺀 2.95초 정도가 cProfile 프로파일링을 진행하면서 발생한 오버헤드 비용 시간을 간접적으로 추론할 수 있다.
이제 다음의 ncalls, tottime, percall, cumtime, percall 항목에 대해 살펴보자. ncalls는 말 그대로 해당 함수를 호출한 횟수를 의미한다. 그리고 tottime은 다른 함수를 호출하는 데 사용한 시간들을 제외하고 순수 자신의 코드만 실행하는 데 걸린 시간을 의미한다. 그리고 percall은 2개로 표시되는데 먼저 tottime 옆의 percall은 해담 함수를 1번 호출하는 데 걸린 시간을 의미한다. 그리고 cumtime은 실행 누적 시간을, cumtime 옆의 percall은 해당 함수를 한 번 호출하는 데 걸린 누적 시간을 의미한다.
그러면 한 줄 예시를 통해서 알아보자. 위 화면에서 filename이 main.py 스크립트의 7번째 줄인 calculate_z_serial_purepython 함수를 호출했을 때의 결과를 보자. 먼저 해당 함수의 호출 횟수(ncalls)은 1회였고, 해당 함수를 호출한 횟수(1회) 만큼 실행하는 데 걸린 총 시간(tottime)은 6.698초이며, 역시 해당 함수를 한 번 호출하는 데 걸린 시간(percall)도 6.698초이다.(왜냐하면 해당 함수를 1회만 호출했기 때문에 tottime 과 percall 수치가 같음) 그리고 해당 함수를 호출한 후 실행이 완료되었을 때의 누적 시간(cumtime)은 8.15초이고, 해당 함수를 한 번 호출하는 데 걸린 누적 시간도 역시 8.15초이다.(왜냐하면 호출 횟수(ncalls)가 한 번이기 때문)
한 가지를 더 살펴보자. 위 화면의 빨간색 네모칸을 보자. built-in method builtins.abs 라는 함수 즉, 우리가 흔히 사용하는 파이썬의 빌트인 abs() 함수를 실행한 부분인데, 이 함수를 54,283,802번을 호출했음을 알 수 있다. 그리고 54,283,802번 호출을 다 하는데 걸린 시간은 1.452초이고, abs() 함수를 한 번 호출하는 데 걸린 시간(tottime 옆의 percall)은 거의 0초에 수렴한다.(물론 실제 0초는 아니다. 화면에서는 표시가 되지 않았지만 매우 micro한 0초이고 이것이 54,283,802번 합쳐져서 총 시간이 1.452초 걸린 것이다)
여기서 흥미로운 점은 abs() 함수를 54,283,802번 다 호출하는 데 걸린 시간인 1.452초와 그 바로 위의 calculate_z_serial_purepython 함수를 호출하는 데 걸린 시간인 6.698초를 합치면 대략 8.15초가 되는 것을 알 수 있다.
이렇게 해서 cProfile 프로파일링 결과물을 해석할 수 있었다. 위 결과물을 파일 형태로도 저장할 수 있다. 물론 리다이렉션(>>)을 통해서 터미널 출력 결과를 파일로 저장할 수 도 있지만 -o 옵션을 사용해서 .stats 확장자의 파일로 저장할 수 있다.
python -m cProfile -o profile.stats main.py
그리고 아래의 스크립트 형태로 프로파일링 결과물을 로드하고 출력시킬 수 있다.
import pstats
p = pstats.Stats("profile.stats")
p.sort_stats("cumulative") # 터미널에서 -s cumulative 옵션 효과와 동일
print(p.print_stats())
해당 목차의 문두에서도 언급했지만 cProfile은 위처럼 대략적으로 어느 지점에서 실행 시간이 오래걸렸는지 파악하기 쉽다. 하지만 함수 안의 각 줄의 정보가 아니라 함수 호출 자체의 정보만 얻을 수 있기 때문에 cProfile로 코드의 라인 바이 라인에서 시간이 얼마나 걸렸는지는 알 수가 없다.
cProfile에 대한 내용을 마무리하기 전에 마지막으로 cProfile로 생성한 프로파일링 결과를 시각화할 수 있는 snakeviz에 대해서 알아보도록 하자. snakeviz가 등장하기 전에는 runsnake 라는 도구가 있었다.
snakeviz를 사용하면 cProfile의 결과를 고차원적으로 관찰할 수 가 있다. 보통 더 오랜 시간을 소비한 영역을 더 큰 상자로 표시한다. snakeviz는 주로 처음 접하는 대규모 코드를 분석해야 할 때 유용하다고 한다. snakeviz가 그리는 다이어그램은 CPU의 사용 정도를 시각화 하므로, 어떤 부분에서 CPU를 많이 사용하는지 쉽게 찾아낼 수 있다. snakeviz를 이용하기 위해서는 pip install 로 설치하면 된다.
pip install snakeviz
그리고 아래 명령어를 수행하면 되는데, 이 때 직전에서 배운 cProfile -o 옵션으로 프로파일링 결과를 export 해준 .stats 확장자의 파일을 인자로 넣어준다.
python -m snakeviz {YOUR FILE.stats}
위 명령어를 실행하면 자동으로 웹 브라우저가 하나 뜨게 되고, 그곳에 snakeviz로 프로파일링 결과를 시각화한 UI가 보여진다. 만약 웹 브라우저가 자동으로 뜨지 않는다면 명령어를 실행한 터미널 콘솔 화면을 살펴보자. URL이 보일 것이다. 그것을 클릭해주자. 어쨌건 시각화한 결과는 아래와 같다.
가운데 색깔이 입혀져있는 다이어그램의 맨 위 지점이 프로그램 진입점을 의미한다. 각 직사각형인 다이어그램의 너비는 프로그램 실행에 걸린 전체 시간을 의미한다. 그리고 아래 다이어그램으로 갈수록 좀 더 구체적으로 어떤 함수가 얼마나 시간이 걸렸는지 보여준다. 다이어그램에 커서를 갖다 대면 특정 함수가 다이어그램의 어느 면적을 차지하는지 표시해도 해준다.
그리고 맨 아래에 위에서 우리가 터미널 결과로 살펴본 통계치도 보여준다. 의미는 위에서 알아보았으므로 중복해서 설명하지는 않겠다. 복습 차원에서 표를 보고 의미를 되새김질 해보는 것도 좋다.
이렇게 snakeviz는 이쁜 UI로 정보를 제공해준다. snakeviz를 통한 시각화는 주로 동료들 간에 성능 결과를 공유할 때 주로 사용하면 편하다.
4. line_profiler로 함수 한 줄씩 측정하기
다음은 cProfile에서는 제공하지 않는 함수 라인 바이 라인으로 실행시간을 측정할 수 있는 line_profiler 이다. 우선 line_profiler를 사용하기 위해서는 pip으로 설치해주어야 한다.
pip install line_profiler
사용 방법은 라인 바이 라인으로 실행 시간을 측정할 함수에다가 @profile 데커레이터를 붙여주면 된다. 예시 코드는 아래와 같다. 우리는 calculate_z_serial_purepython 함수의 실행 시간을 측정할 것이다.
import time
from line_profiler import profile
x1, x2, y1, y2 = -1.8, 1.8, -1.8, 1.8
c_real, c_imag = -0.62772, -.42193
@profile
def calculate_z_serial_purepython(maxiter, zs, cs):
output = [0] * len(zs)
for i in range(len(zs)):
n = 0
z = zs[i]
c = cs[i]
while abs(z) < 2 and n < maxiter:
z = z * z + c
n += 1
output[i] = n
return output
def calc_pure_python(desired_width, max_iterations):
x_step = (x2 - x1) / desired_width
y_step = (y1 - y2) / desired_width
x, y = [], []
ycoord = y2
while ycoord > y1:
y.append(ycoord)
ycoord += y_step
xcoord = x1
while xcoord < x2:
x.append(xcoord)
xcoord += x_step
zs, cs = [], []
for ycoord in y:
for xcoord in x:
zs.append(complex(xcoord, ycoord))
cs.append(complex(c_real, c_imag))
print("Length 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")
assert sum(output) == 53283802
if __name__ == "__main__":
calc_pure_python(desired_width=1000, max_iterations=500)
그리고 아래의 kernprof 명령어를 실행해주어 함수 각 줄의 통계치를 제공해준다. 참고로 kernprof은 '커네프로프'라고 읽으며, kernel의 'kern', profile의 'prof' 의 합성어이다.
kernprof -l -v main.py
위 명령어의 $-l$ 옵션은 한 줄씩 프로파일하겠다는 의미이며, v 옵션은 출력 결과를 자세하게 보여주도록 한다. 위 명령어를 실행하면 나중에 line_profiler로 분석할 수 있는 .lprof 라는 확장자의 파일도 생긴다. 프로파일링 결과는 다음과 같다.
프로파일링 대상의 함수가 실행된 총 순수 시간은 18.3초이다. 이전에 cProfile로 측정했을 때는 프로파일링 오버헤드 시간을 포함했어도 8초였던 반면 이번엔 18.3초로 약 10초 가량 늘었다. 이 또한 line_profiler의 오버헤드 비용을 의미한다. 각 항목의 Time 이라는 항목은 해당 라인의 실행 시간을 의미한다. 단위는 마이크로초로 해당 초를 100만으로 나누면 초 단위 변환이 된다. 그래서 가장 많이 걸린 while 문에서 8.4초 가량 소요되었음을 알 수 있다. 다음은 % Time 항목이다. 이 부분은 함수가 실행된 전체 시간(위 화면에서는 18.317초) 중 해당 라인이 몇 % 소비했는지를 나타낸다.
위 결과를 보면 while 문이 8.4초로 전체 실행 시간의 46%를 차지했고, 그 다음으로 z 변수를 갱신하는 데는 약 5초, n 값을 더하는 데에는 4.4초가 걸렸음을 알 수 있다. 사실 변수를 갱신하고 1을 더하는 연산이 왜이렇게 오래걸리지? 하겠지만 아쉽게도 이는 Python의 동적 타입 검사 기능 때문이다. 프로그래머가 동일한 변수를 계속 사용하도록 저렇게 작성해도 Python은 계속 매번 해당 변수의 타입을 동적으로 검사한다.
그런데 위 while 문에서는 조건이 2개이다. 바로 abs(z) < 2 와 n < maxiter 라는 2개의 조건문이다. 이 둘 중에 어떤 것이 더 시간을 잡아먹는지 일종의 '가설'을 세우고 이 부분을 디테일하게 분석해보자. 먼저 아래처럼 코드를 수정하고 동일하게 line_profiler를 사용해서 프로파일링 해보자.
@profile
def calculate_z_serial_purepython(maxiter, zs, cs):
output = [0] * len(zs)
for i in range(len(zs)):
n = 0
z = zs[i]
c = cs[i]
# 수정된 부분
while True:
cond1 = abs(z) < 2
cond2 = n < maxiter
if cond1 and cond2:
z = z * z + c
n += 1
else:
break
output[i] = n
return output
그런데 웬걸? 이번에 프로파일링 시간이 더 늘어 30초가 걸렸다. 그리고 각 라인별로 실행된 시간을 살펴보니 프로파일링을 분석하기가 더 어려워졌다. 이는 코드가 수정된 부분으로 인해 다른 요소 때문에 프로파일링 분석을 더 어렵게 만든 것이다. 그래도 찾을 수 있는 부분은 cond1 와 cond2 간의 실행 시간을 보면 cond2 즉, n < maxiter 조건식이 좀 더 실행시간이 덜 걸린 것을 찾을 수 있다. 그러면 이제 단순하게 cond1인 abs(z) < 2 라는 조건식과 cond2인 n < maxiter 조건식 간에 어떤 것이 실행시간이 더 짧게 걸리는지 timeit 모듈을 통해서 살펴보고, 우리가 세운 가설이 맞는지 증명해보자.
위 결과는 두 조건식을 100만번 7회 테스트를 한 결과이다. 보면 n < maxiter 라는 조건식이 13.7 나노초, abs(z) < 2가 39.2 나노초로 n < maxiter 라는 조건식이 약 3배 빠른 것을 알 수 있다. 그러면 그러므로 while 조건문을 정의할 때는 n < maxiter 라는 조건식을 앞에 두는 것이 좋을 것이다라는 가설을 세울 수 있다.
우리는 이제 이런 가설을 하고 조건식 순서를 기존과 바꾸어 즉, n < maxiter 라는 조건을 앞에 두어 전/후 프로파일링 결과를 비교해보도록 하자.
하지만 조건식을 바꾼 14번째 줄의 실행 시간을 비교하면 8.4초로 동일하다. 그리고 함수가 실행된 총 시간(Total time)도 보면 0.1초 차이나긴 하지만 거의 동일하다.
물론 위 코드는 추후에 배울 파이썬이나 PyPy를 이용하면 성능 향상을 기대할 수 있지만 해당 포스팅에서는 범위가 벗어나 소개하지 않는다. 어쨌건 우리는 위 가설을 세우고 검증해보면서 프로파일링 시 몇 가지 팁을 배울 수 있다.
- 쉽게 검증할 수 있는 가설을 세워라
- 가설을 검증할 수 있도록 코드를 수정해라. 이 때, 한 번에 한 가지 가설만 검증 시도 해라(두 개이상의 가설을 한꺼번에 검증하면 변수가 많아져 제대로 된 프로파일링을 하지 못한다)
- 결론을 뒷받침하기에 충분한 근거를 여러가지 프로파일링 기법을 통해 확보해라
- 가설을 검증할 때, 소스코드에 입력시킬 데이터는 대표성이 있는 데이터를 사용해라(ex. 평소 request의 크기로 테스트해라)
5. PySpy로 실행 중인 프로세스 측정하기
다음은 py-spy 라는 샘플링 프로파일러에 대해 알아보자. 지금까지 알아본 프로파일링 도구들은 소스코드를 실행하는 동시에 프로파일링을 수행했다. 하지만 이번에 알아볼 py-spy라는 도구는 이미 실행 중인 파이썬 프로세스에 대해서 프로파일링을 수행하는 도구이다. 결과 화면은 리눅스의 CPU 사용량, 메모리 사용량 등 전반전인 상황을 실시간으로 모니터링하는 명령어인 top의 출력 화면과 비슷한 방식으로 표시해준다. py-spy는 프로파일링 대상이 되는 소스코드와 함께 프로세스 외부에서 실행되므로 프로파일링 대상이 되는 소스코드의 실행 시점에 미치는 영향이 거의 없다. 그래서 py-spy는 보통 운영 환경에서 오랫동안 실행되는 프로세스나 설치 요구사항이 복잡한 프로그램을 분석할 때 유용하다. 참고로 py-spy는 특정 함수에 해당하는 부분만 프로파일링 하는 것은 불가능하다.
py-spy를 이용하기 위해서는 우선 설치를 먼저해주어야 한다.
pip install py-spy
이제 py-spy를 활용해서 프로파일링을 수행해보자. 앞에서도 언급했지만 py-spy는 이미 실행중인 프로세스에 대해 프로파일링을 수행하므로 이미 실행중인 프로세스에 대한 아이디 즉, PID를 인자로 넣어주어 측정할 수 있다.
sudo py-spy top --pid {PID}
위 화면과 같이 실시간으로 결과를 볼 수 있다. py-spy는 위 화면에서 어떤 함수가 가장 오래 걸리는지 매초 갱신해서 표시해준다. 위 예시에서는 calculate_z_serial_purepython 이라는 함수가 가장 시간이 오래걸리고 있음을 볼 수 있다. 또한 py-spy는 cProfile의 snakeviz처럼 시각화를 하여 프로파일링 결과를 표시할 수 있다. py-spy에서는 이를 화염(flame) 그래프로 표시한다. 화염 그래프로 표시할 때는 방금처럼 PID 번호를 지정해주어도 되고, 코드 실행과 동시에 적용할 수도 있다. 각 방법에 대한 명령어는 아래와 같다.
# PID
sudo py-spy record --pid {PID}
# 코드 실행과 동시에
sudo py-spy record -- python main.py
위 명령어를 수행하면 svg 확장자로 하나의 파일이 생기는데, 열어보면 아래와 같이 화염 그래프가 보여진다.
가로 길이는 전체 프로그램의 실행 시간을 의미하고 각 층은 바로 위층의 함수가 호출한 함수들의 실행 시간이다.
6. 바이트코드로 살펴보기
이번엔 파이썬의 가상 머신에서 사용하는 내부 바이트코드를 살펴봄으로써 밑바닥에서 벌어지는 일을 조금 이해해보도록 하자. 이 부분을 이해하면 왜 특정 부분에서 코드가 느리게 동작하는지 좀 더 로우 레벨에서 인식할 수 있다. 바이트코드가 더 많이 생성된다는 것은 그만큼 동작하는 과정이 더 많다는 것이고 이는 결국 느린 실행 시간으로 이어지게 된다. 반대로 바이트코드가 더 적게 생성될 수록 빠른 실행 시간을 보장한다.
파이썬에서는 dis 라는 기본 내장 모듈을 사용해서 코드나 모듈의 역어셈블 결과를 출력해준다. 즉, 함수나 모듈의 동작 순서를 바이트코드로 표현해서 반환해준다. 아래 화면은 위에서 사용한 함수인 calculate_z_serial_purepython 이라는 함수의 바이트코드 결과이다. 결과 화면이 다소 길기 때문에 아래 더보기를 클릭해서 살펴보도록 하자.
8 0 LOAD_CONST 1 (0)
2 BUILD_LIST 1
4 LOAD_GLOBAL 0 (len)
6 LOAD_FAST 1 (zs)
8 CALL_FUNCTION 1
10 BINARY_MULTIPLY
12 STORE_FAST 3 (output)
9 14 LOAD_GLOBAL 1 (range)
16 LOAD_GLOBAL 0 (len)
18 LOAD_FAST 1 (zs)
20 CALL_FUNCTION 1
22 CALL_FUNCTION 1
24 GET_ITER
>> 26 FOR_ITER 46 (to 120)
28 STORE_FAST 4 (i)
10 30 LOAD_CONST 1 (0)
32 STORE_FAST 5 (n)
11 34 LOAD_FAST 1 (zs)
36 LOAD_FAST 4 (i)
38 BINARY_SUBSCR
40 STORE_FAST 6 (z)
12 42 LOAD_FAST 2 (cs)
44 LOAD_FAST 4 (i)
46 BINARY_SUBSCR
48 STORE_FAST 7 (c)
13 50 LOAD_FAST 5 (n)
52 LOAD_FAST 0 (maxiter)
54 COMPARE_OP 0 (<)
56 POP_JUMP_IF_FALSE 55 (to 110)
58 LOAD_GLOBAL 2 (abs)
60 LOAD_FAST 6 (z)
62 CALL_FUNCTION 1
64 LOAD_CONST 2 (2)
66 COMPARE_OP 0 (<)
68 POP_JUMP_IF_FALSE 55 (to 110)
14 >> 70 LOAD_FAST 6 (z)
72 LOAD_FAST 6 (z)
74 BINARY_MULTIPLY
76 LOAD_FAST 7 (c)
78 BINARY_ADD
80 STORE_FAST 6 (z)
15 82 LOAD_FAST 5 (n)
84 LOAD_CONST 3 (1)
86 INPLACE_ADD
88 STORE_FAST 5 (n)
13 90 LOAD_FAST 5 (n)
92 LOAD_FAST 0 (maxiter)
94 COMPARE_OP 0 (<)
96 POP_JUMP_IF_FALSE 55 (to 110)
98 LOAD_GLOBAL 2 (abs)
100 LOAD_FAST 6 (z)
102 CALL_FUNCTION 1
104 LOAD_CONST 2 (2)
106 COMPARE_OP 0 (<)
108 POP_JUMP_IF_TRUE 35 (to 70)
16 >> 110 LOAD_FAST 5 (n)
112 LOAD_FAST 3 (output)
114 LOAD_FAST 4 (i)
116 STORE_SUBSCR
118 JUMP_ABSOLUTE 13 (to 26)
17 >> 120 LOAD_FAST 3 (output)
122 RETURN_VALUE
위 결과화면의 첫 번째 열은 원래 소스코드 즉, calculate_z_serial_purepython 함수의 라인 넘버를 의미한다. 두 번째 열의 '>>' 기호는 코드의 다른 지점에서 점프해오는 지점을 의미한다. 주로 for loop 문에서 표시된다. 세 번째 열은 연산 주소, 네 번째 열은 연산 이름, 다섯 번째 열은 해당 연산에 전달하는 매개변수를, 여섯번째 열은 이해를 돕기 위해 원래 파이썬 코드를 같이 출력한다.
그러면 바이트코드를 언제 살펴볼지, 그리고 살펴봄으로써 얻는 효과를 체감하기 위해 동일한 작업을 다른 방법으로 수행하는 2개의 함수를 살펴보자.
def fn_expensive(n=1_000_000):
total = 0
for i in range(n):
total += i
return total
def fn_cheap(n=1_000_000):
return sum(range(n))
assert fn_expensive() == fn_cheap(), "expect identical result from two funcitons"
위 2개의 함수는 동일하게 0부터 n-1 까지의 합을 계산하는 기능을 한다. 하지만 세부적으로 동작하는 단계는 약간 다르다. 물론 위 함수 로직이 매우 간단하기에 사람의 눈으로는 당연히 fn_cheap 이라는 함수가 조금 더 시간이 덜 걸릴 것이다 라고 생각할 수도 있다. 하지만 이것도 여전히 직관에 의존하는 것이다. 우린 정말 이 두 함수 간의 동작 과정에 차이가 있는지 살펴보기 위해 각 함수의 바이트 코드를 살펴보자. 먼저 fn_expressive 라는 함수의 바이트 코드이다.
4 0 LOAD_CONST 1 (0)
2 STORE_FAST 1 (total)
5 4 LOAD_GLOBAL 0 (range)
6 LOAD_FAST 0 (n)
8 CALL_FUNCTION 1
10 GET_ITER
>> 12 FOR_ITER 6 (to 26)
14 STORE_FAST 2 (i)
6 16 LOAD_FAST 1 (total)
18 LOAD_FAST 2 (i)
20 INPLACE_ADD
22 STORE_FAST 1 (total)
24 JUMP_ABSOLUTE 6 (to 12)
7 >> 26 LOAD_FAST 1 (total)
28 RETURN_VALUE
다음은 fn_cheap 함수의 바이트 코드이다.
11 0 LOAD_GLOBAL 0 (sum)
2 LOAD_GLOBAL 1 (range)
4 LOAD_FAST 0 (n)
6 CALL_FUNCTION 1
8 CALL_FUNCTION 1
10 RETURN_VALUE
바이트 코드의 양만 보더라도 fn_cheap 이라는 함수가 현저히 매우 적음을 볼 수 있다. fn_expensive 의 바이트 코드를 일부 살펴보면, 우선 for loop를 의미하는 FOR_ITER 연산에서는 매번 StopIteration 예외가 발생하는지를 검사할 것이다. 그리고 연산 주소가 20인 INPLACE_ADD에 해당하는 즉, 파이썬 코드에서는 6번째 줄의 "+= i" 라는 부분에서 i 라는 변수의 타입을 검사하고, 그 객체에 __add__ 라는 매직 메소드가 있는지도 살펴보고, 있다면 호출하는 과정을 매번 진행한다. 이렇게 추가적인 검사 과정이 누적되다 보면 성능의 하락 원인이 된다.
실제로 timeit 모듈을 사용해서 2개의 함수의 실행 시간을 한번 측정해보자.
결과 화면을 보면 fn_cheap() 함수가 9.04 밀리세컨드가 소요된 반면 fn_expensive() 함수는 23.3 밀리세컨드가 소요된 것을 볼 수 있다.
이렇게 해서 파이썬에서 프로파일링하는 여러가지 기법에 대해 살펴보았다. 긴 내용이였지만 컨텐츠를 Wrap-up 하면 핵심 내용은 다음과 같다.
- 프로파일링을 수행할 때는 일부 코드만 떼내어 측정하도록 하고 가설을 반드시 세우고 검증하도록 하자
- 가장 기본적인 프로파일링 도구는 timeit, time, 데코레이터를 활용하자
- 유닉스의 time 명령어 : 실행시간이 짧은 코드가 실행되기 까지 걸리는 시간을 파악하는 데 유용
- cProfile 과 snakeviz : 개괄적인 성능을 측정해 어떤 함수가 병목 지점인지 파악
- line_profiler, memory_profiler : 라인 바이 라인 측정 도구로, 병목 지점으로 예상되는 함수의 디테일한 병목 지점이 어디인지 파악
- py-spy: 이미 실행중인 코드 또는 프로세스에 대해 프로파일링을 수행할 때 사용
- 바이트 코드 : 생성된 바이트 코드가 얼마나 되는지, 내장 함수로 최적화할 수 없는지 파악
다음 챕터부터는 큰 데이터를 저장할 때 합리적인 선택을 할 수 있도록 하기 위해 파이썬의 자료구조(튜플, 리스트, 딕셔너리, 셋(set))이 어떻게 구현되었는지 배워보도록 하자.
'Python > 고성능파이썬' 카테고리의 다른 글
| [고성능파이썬] 이터레이터(iterator)와 제네레이터(generator) (0) | 2024.03.30 |
|---|---|
| [고성능파이썬] 사전(dictionary) 과 셋(set) (0) | 2024.03.25 |
| [고성능파이썬] 리스트(list)와 튜플(tuple)에 관하여 (1) | 2024.02.18 |
| [고성능파이썬] 고성능 파이썬을 어떻게 실현시킬 수 있을까? (0) | 2023.12.14 |
