[Python] 프로파일링 (profiling)
Introduction
파이썬 코드를 작성하다 보면 성능 최적화를 위해 코드의 실행 시간을 정확히 측정하고 싶을 때가 있다.
물론 아래와 같이 time 모듈을 이용해 시간 성능 저하가 예상되는 일부 코드 블럭의 실행 시간을 직접 측정해 볼 수 있지만, 요소별로 실행 시간을 측정하기가 불편하고, 무엇보다도 파이썬의 동적인 특성으로 인해 예상되는 지연 구간과 실제 지연이 일어나는 부분이 다를 수 있다는 문제가 있다.
from time import time
from math import sin, cos, pi
def projectile_landing_position(velocity, angle, g_constant):
"""
XY평면 (0,0) 좌표에서 X축 기준 angle(deg,<180,0<) 방향으로
velocity(0<) 값의 속력으로 출발한 물체가, -Y축 방향
중력 가속도 g(0<) 하 얼마의 x 값에서 y=0에 도달할 지 계산하는 함수.
"""
if velocity < 0:
raise ValueError("velocity는 0과 같거나 커야 합니다")
velocity_x = velocity * cos(angle / 180 * pi)
velocity_y = velocity * sin(angle / 180 * pi)
terminal_time = velocity_y / g_constant
landing_position = velocity_x * terminal_time
return landing_position
start = time()
projectile_landing_position(5.0, 30, 9.8)
end = time()
print(f"Elapsed time: {end-start}")
>>>
Elapsed time: 0.06005454063415527예전 글의 예제다. 두 time() 호출 값 차이를 이용해 코드 실행 시간을 측정했다.
따라서 프로그램을 실행시켰을 때 각 코드 부분이 얼마의 실행 시간을 소모하는지 알려주는 프로파일러 (profiler) 툴을 사용해, 전체적으로 봤을 때 최적화가 필요한 부분을 우선적으로 검토하는 것이 효율적인 성능 개선 방향이 될 것이다.
Sample Code
프로파일링 예제를 통해 샘플 코드의 시간 성능을 한번 측정해 보자.
먼저 프로파일링을 위한 함수를 아래와 같이 작성했다.
# user_module.py
from math import sin, cos, pi
def update_position(x, y, vel_x, vel_y, timedelta):
x_updated = x + vel_x * timedelta
y_updated = y + vel_y * timedelta
return x_updated, y_updated
def update_velocity(vel_x, vel_y, g_constant, timedelta):
vel_x_updated = vel_x
vel_y_updated = vel_y - g_constant * timedelta
return vel_x_updated, vel_y_updated
def projectile_landing_position_numerical(velocity, angle, g_constant, timedelta):
"""
XY평면 (0,0) 좌표에서 X축 기준 angle(deg,<180,0<) 방향으로
velocity(0<) 값의 속력으로 출발한 물체가, -Y축 방향
중력 가속도 g(0<) 하 얼마의 x 값에서 y=0에 도달할 지 수치적으로 계산하는 함수.
"""
if velocity < 0:
raise ValueError("velocity는 0과 같거나 커야 합니다")
pos_x = 0.0
pos_y = 0.0
vel_x = velocity * cos(angle / 180 * pi)
vel_y = velocity * sin(angle / 180 * pi)
terminal_time = 0.0
while pos_y >= 0:
pos_x, pos_y = update_position(pos_x, pos_y, vel_x, vel_y, timedelta)
vel_x, vel_y = update_velocity(vel_x, vel_y, g_constant, timedelta)
terminal_time += timedelta
landing_position = pos_x
return landing_position
이전 예제의 코드를 수치적으로 계산하도록 수정해 실행 시간을 일부러 조금 늘렸다. 그리고 프로파일링을 위해, 프로파일러에 넘겨줄 랜덤 인자를 받는 테스트 함수를 하나 정의하자.
from random import random, randint
from user_module import projectile_landing_position_numerical
data = [random() * 5, randint(0, 90), random() * 10, 0.00001]
test = lambda: projectile_landing_position_numerical(*data)cProfile Module
이제 프로파일러를 이용해 테스트 함수의 시간 성능을 프로파일링 할 차례다. 파이썬에서는 기본적으로 제공하고 있는 프로파일러가 두 종류 있다 (3.9.5 기준). 바로 profile 모듈과 cProfile 모듈이다. 둘 다 프로그램의 어떤 부분이 얼마나 자주 실행되었고, 얼마나 오래 실행되었는지를 기록하고 보여주는 기능을 하고 있지만, 공식 도큐멘테이션에서는 cProfile 모듈을 사용하는 것을 권장하고 있다.
둘에 어떤 차이가 있냐 하면, 기본적으로 profile 모듈은 순수하게 파이썬 언어로 작성된 모듈이며 cProfile 모듈은 C 언어 확장 모듈인데 (파이썬에서 C/C++ 라이브러리를 이용할 수 있다고 생각하면 된다), 후자가 전자에 비해 프로파일링 시 대상이 되는 프로그램에 더욱 적은 부하를 주기 때문에 더 정확한 성능 평가가 가능하다고 한다.
참고로, 프로파일링 시에는 외부 자원을 이용하는 함수 부분이 시간 지연을 일으키지 않도록 (I/O 병목) 해당되는 부분들을 잘 수정해 코드 자체의 성능을 평가할 수 있도록 만들어 놓는 것이 좋다.
이제 cProfile 모듈을 사용해 프로파일링을 수행해 보자.
from cProfile import Profile
profiler = Profile()
profiler.runcall(test)
먼저 Profile 객체의 인스턴스를 생성하고, runcall 메서드를 사용해 test 함수를 프로파일링 했다.
runcall 메서드는 단일 함수의 프로파일링에 사용할 수 있는 기능이다. 만약 커맨드 라인 단위로 프로파일링을 수행하고 싶다면, 아래와 같이 run 과 같은 다른 메서드를 이용할 수 있다.
from cProfile import Profile
profiler = Profile()
profiler.run('test()')Print Profile Result
이렇게 수행된 프로파일링 결과는 바로 볼 수 있는 것이 아니라, 아래와 같이 기본 모듈인 pstats 를 추가로 이용해 성능 통계 값을 원하는 대로 정렬, 선별해 출력할 수 있다. 예시로, 아래의 strip_dirs 메서드는 모듈 이름을 출력할 때 상대 경로만을 보여주며 (기본적으론 절대 경로가 출력되는데 조금 길다....), sort_stats 메서드는 결과를 누적 실행 시간 기준으로 정렬해 주는 기능을 수행한다. 한번 결과를 보자.
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
>>
144315 function calls in 0.054 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.054 0.054 main.py:6(<lambda>)
1 0.030 0.030 0.054 0.054 user_module.py:17(projectile_landing_position_numerical)
72155 0.014 0.000 0.014 0.000 user_module.py:5(update_position)
72155 0.010 0.000 0.010 0.000 user_module.py:11(update_velocity)
1 0.000 0.000 0.000 0.000 {built-in method math.sin}
1 0.000 0.000 0.000 0.000 {built-in method math.cos}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
꽤 깔끔하게 정리를 해 준다.
이 이외에도 sort_stats 에 다른 인자를 전달해 원하는 대로 결과를 정렬할 수 있다. 아래의 사진을 참고하자.
Overhead Test
아까 profile 모듈은 프로그램에 꽤 큰 부하를 줘 추천하지 않는다고 했는데, 같은 인풋을 사용해 테스트 했을 때 결과가 얼마나 달라질까? 한번 확인해 보자.
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
>>
144316 function calls in 0.297 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.297 0.297 profile:0(<function <lambda> at 0x000001EA5538F280>)
1 0.000 0.000 0.281 0.281 main.py:6(<lambda>)
1 0.156 0.156 0.281 0.281 user_module.py:17(projectile_landing_position_numerical)
72155 0.094 0.000 0.094 0.000 user_module.py:5(update_position)
72155 0.031 0.000 0.031 0.000 user_module.py:11(update_velocity)
1 0.016 0.016 0.016 0.016 :0(setprofile)
0 0.000 0.000 profile:0(profiler)
1 0.000 0.000 0.000 0.000 :0(cos)
1 0.000 0.000 0.000 0.000 :0(sin)
profile 모듈로 대체했을 때 큰 오버헤드로 인해 결과가 무시할 수 없을 정도로 (전체 실행 시간 0.054초 -> 0.297초) 차이나는 것을 볼 수 있다.
Other Features
참고로 위의 출력 결과에서 ncall은 프로파일러 실행 중 특정 함수의 호출 횟수, tottime은 특정 함수가 실행된 시간 합계 (다른 함수가 내부에서 실행된 시간은 제외함), percall은 호출 횟수 당 시간, cumtime은 tottime과 다르게 함수 내부에서 실행된 다른 함수의 시간까지도 포함한 시간이다.
* ncall이 3/1 과 같이 표현되어 있으면, 함수가 재귀 호출되었다는 뜻으로 앞 숫자는 총 호출 횟수, 뒤 숫자는 primitive 호출 횟수를 뜻한다.
만약 print_stats 대신 print_callers 메서드를 호출하면 아래와 같이 함수들의 호출 관계를 명확하게 정리해서 볼 수 있다.
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()
>>
144315 function calls in 0.052 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.052 0.052 main.py:6(<lambda>)
1 0.029 0.029 0.052 0.052 user_module.py:17(projectile_landing_position_numerical)
72155 0.013 0.000 0.013 0.000 user_module.py:5(update_position)
72155 0.010 0.000 0.010 0.000 user_module.py:11(update_velocity)
1 0.000 0.000 0.000 0.000 {built-in method math.sin}
1 0.000 0.000 0.000 0.000 {built-in method math.cos}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
from pstats import Stats
stats = Stats(profiler)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_callers()
>>
Ordered by: cumulative time
Function was called by...
ncalls tottime cumtime
main.py:6(<lambda>) <-
user_module.py:17(projectile_landing_position_numerical) <- 1 0.029 0.052 main.py:6(<lambda>)
user_module.py:5(update_position) <- 72155 0.013 0.013 user_module.py:17(projectile_landing_position_numerical)
user_module.py:11(update_velocity) <- 72155 0.010 0.010 user_module.py:17(projectile_landing_position_numerical)
{built-in method math.sin} <- 1 0.000 0.000 user_module.py:17(projectile_landing_position_numerical)
{built-in method math.cos} <- 1 0.000 0.000 user_module.py:17(projectile_landing_position_numerical)
{method 'disable' of '_lsprof.Profiler' objects} <-
이 기능은 한 함수가 다른 여러 함수에서 제각각 호출되어도, 결과를 따로 분리해 보여주기 때문에 어떤 함수가 특정 함수를 호출했으며, 특정 함수가 어떤 부분에서 가장 많이 호출 되었는지 더 clear하게 볼 수 있다는 장점이 있다.
그런데 이렇게 프로파일러를 이용해 프로파일링을 한번 하고, 다시 Stats 모듈을 가져와 여러 라인을 통해 결과를 출력하는 과정이 불편하게 느껴질 수도 있다. 그래서 사실 이 모듈엔 약식으로 간단하게 프로파일링을 수행할 수 있는 기능도 포함되어 있다. 한번 예제로 보도록 하자.
import cProfile
cProfile.run('test()')
>>
144317 function calls in 0.054 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.054 0.054 <string>:1(<module>)
1 0.000 0.000 0.054 0.054 main.py:6(<lambda>)
72155 0.010 0.000 0.010 0.000 user_module.py:11(update_velocity)
1 0.030 0.030 0.054 0.054 user_module.py:17(projectile_landing_position_numerical)
72155 0.014 0.000 0.014 0.000 user_module.py:5(update_position)
1 0.000 0.000 0.054 0.054 {built-in method builtins.exec}
1 0.000 0.000 0.000 0.000 {built-in method math.cos}
1 0.000 0.000 0.000 0.000 {built-in method math.sin}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
표현이 좀 그렇지만 적당히 알아서 (....) 프로파일링 결과를 출력해 준다. 맨 오른쪽의 텍스트 문자열을 기준으로 정렬을 해 주고 있다 (Ordered by: standard name).
이 방법 이외에도 스크립트로 프로파일러를 호출해 다른 스크립트를 프로파일링 하는 것도 가능하다.
Script-level Profiling
python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)- -o 옵션은 결과 출력 대신 프로파일 결과를 파일의 형태로 저장해 준다.
- -s 는 sort_stats() 인자 중 하나를 넣어주면, 그 방식대로 정렬해 결과를 보여준다. (-o가 제공되면 무시됨)
- -m 은 스크립트 대신 모듈이 프로파일링 되도록 한다. (cProfile 기준 파이썬 버전 3.7부터)
파일로 저장된 결과는 앞의 예제와 똑같은 방식으로 pstats 모듈을 사용해 데이터를 읽어와 처리하고, 출력할 수 있다.
(예시)
python -m cProfile -o {SAVE_DIR} main.py)main.py의 실행 종료 후에 SAVE_DIR 경로로 파일이 하나 생기고,
from pstats import Stats
stats = Stats("SAVE_DIR")
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_callers()위와 같이 pstats.Stats를 호출할 때 경로를 지정해 주면 바로 결과를 읽어올 수 있다.
사실 이렇게 파이썬 기본 프로파일러를 쓰는 방법 이외에도 timeit 모듈을 이용해 코드 조각 단위로 시간을 측정하는 방법도 있고, 이것도 꽤 유용하게 쓰이고 있다. 이에 대해서는 다음 기회에 또 다뤄보고자 한다.
그리고 파이썬 프로파일러에는 이 글에서 간략히 소개한 기능들 이외에 다른 기능들도 많이 있으니, 한번 공식 도큐멘테이션을 참고해 보는 것을 추천한다. 세세한 기술적인 부분들까지 설명이 되어 있어 많은 도움이 될 듯 하다.
References
아래는 참고할 만한 사이트들이다.
파이썬 프로파일러 도큐멘테이션: docs.python.org/ko/3/library/profile.html
timeit 모듈 도큐멘테이션: docs.python.org/ko/3/library/timeit.html?highlight=timeit#module-timeit