코드 성능 측정 및 프로파일링

코드를 개발하고 데이터 처리 파이프라인을 구축하다 보면, 여러 가지 구현 방식 중 하나를 선택해야 할 때가 많습니다. 알고리즘 개발 초기부터 효율성에 너무 매달리는 것은 오히려 독이 될 수 있습니다. 도널드 커누스(Donald Knuth)는 “사소한 효율성에 대해서는 97% 정도 잊어버려도 됩니다. 성급한 최적화는 모든 악의 근원입니다”라는 유명한 말을 남기기도 했습니다.

하지만 일단 코드가 제대로 작동하기 시작하면, 성능을 좀 더 세밀하게 살펴볼 필요가 있습니다. 때로는 특정 명령어의 실행 시간을 확인하는 것만으로도 충분하지만, 어떤 경우에는 복잡한 작업 흐름 중 어느 지점에서 병목(bottleneck)이 발생하는지 찾아내야 할 때도 있습니다. IPython은 이러한 코드 성능 측정과 프로파일링을 위한 다양한 기능을 제공합니다. 이번 섹션에서는 다음과 같은 매직 명령어들을 살펴보겠습니다.

뒤의 네 가지 명령어는 IPython에 기본으로 포함되어 있지 않으므로, line_profiler와 memory_profiler 확장 모듈을 별도로 설치해야 합니다. 이 내용은 이어지는 섹션에서 다루겠습니다.

코드 조각의 시간 측정: %timeit 및 %time

IPython 매직 명령어 섹션에서 맛보았듯이, %timeit 라인 매직과 %%timeit 셀 매직을 사용하면 코드 조각의 반복 실행 시간을 측정합니다.

%timeit sum(range(100))
1.53 µs ± 47.8 ns per loop (mean ± std. dev. of 7 runs, 1000000 loops each)

위 작업은 실행 속도가 매우 빠르기 때문에, %timeit은 자동으로 수많은 반복을 수행하여 정확한 평균치를 구합니다. 반면 실행 속도가 느린 명령어의 경우, %timeit이 알아서 반복 횟수를 줄여가며 측정합니다.

%%timeit
total = 0
for i in range(1000):
    for j in range(1000):
        total += i * (-1) ** j
536 ms ± 15.9 ms per loop (mean ± std. dev. of 7 runs, 1 loop each)

때로는 작업을 여러 번 반복하는 것이 최선의 측정 방식이 아닐 수도 있습니다. 예를 들어 리스트를 정렬하는 작업은 반복해서 측정하면 결과가 왜곡될 수 있습니다. 이미 정렬된 리스트를 다시 정렬하는 것은 섞여 있는 리스트를 정렬하는 것보다 훨씬 빠르기 때문입니다.

import random

L = [random.random() for i in range(100000)]
%timeit L.sort()
1.71 ms ± 334 µs per loop (mean ± std. dev. of 7 runs, 1000 loops each)

이럴 때는 %time 매직 명령어가 더 적절한 선택입니다. 또한 시스템의 일시적인 지연이 전체 결과에 큰 영향을 주지 않는, 실행 시간이 아주 긴 명령어의 시간을 측정할 때도 유용합니다. 섞여 있는 리스트와 이미 정렬된 리스트의 정렬 시간을 각각 측정해 보겠습니다.

import random

L = [random.random() for i in range(100000)]
print("정렬되지 않은 리스트 정렬:")
%time L.sort()
sorting an unsorted list:
CPU times: user 31.3 ms, sys: 686 µs, total: 32 ms
Wall time: 33.3 ms
print("이미 정렬된 리스트 정렬:")
%time L.sort()
sorting an already sorted list:
CPU times: user 5.19 ms, sys: 268 µs, total: 5.46 ms
Wall time: 14.1 ms

이미 정렬된 리스트의 정렬 속도가 얼마나 빠른지 확인해 보세요. 또한 정렬된 리스트라고 해도 %time이 %timeit보다 시간이 더 걸리는 것처럼 보일 수 있습니다. 이는 %timeit이 시스템 호출 등이 측정 결과에 간섭하지 못하도록 내부적으로 정교한 처리를 수행하기 때문입니다. 예를 들어 측정을 방해할 수 있는 파이썬 객체 정리 작업(가비지 컬렉션)을 잠시 멈추기도 합니다. 이러한 이유로 %timeit의 결과가 일반적으로 %time보다 눈에 띄게 빠르게 나옵니다.

%time 역시 %% 셀 매직 구문을 사용해 여러 줄로 된 스크립트의 실행 시간을 측정합니다.

%%time
total = 0
for i in range(1000):
    for j in range(1000):
        total += i * (-1) ** j
CPU times: user 655 ms, sys: 5.68 ms, total: 661 ms
Wall time: 710 ms

%time과 %timeit에 대한 더 자세한 옵션은 IPython 도움말 기능을 통해 확인합니다 (예: %time? 입력).

전체 스크립트 프로파일링: %prun

프로그램은 여러 개의 문장으로 구성되는데, 어떤 맥락에서는 개별 문장의 실행 시간보다 문장 사이의 관계나 흐름 안에서의 시간이 더 중요할 때가 있습니다. 파이썬에는 기본 코드 프로파일러가 내장되어 있지만, IPython은 이를 훨씬 편리하게 사용할 수 있도록 %prun 매직 명령어를 제공합니다.

예시를 위해 간단한 계산을 수행하는 함수를 정의해 보겠습니다.

def sum_of_lists(N):
    total = 0
    for i in range(5):
        L = [j ^ (j >> i) for j in range(N)]
        total += sum(L)
    return total

이제 %prun과 함께 함수를 호출하여 프로파일링 결과를 확인해 보겠습니다.

%prun sum_of_lists(1000000)
 
         14 function calls in 0.932 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5    0.808    0.162    0.808    0.162 <ipython-input-7-f105717832a2>:4(<listcomp>)
        5    0.066    0.013    0.066    0.013 {built-in method builtins.sum}
        1    0.044    0.044    0.918    0.918 <ipython-input-7-f105717832a2>:1(sum_of_lists)
        1    0.014    0.014    0.932    0.932 <string>:1(<module>)
        1    0.000    0.000    0.932    0.932 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

결과 테이블은 각 함수 호출에 소요된 시간을 기준으로 실행 시간의 병목 구간을 보여줍니다. 이 예제에서는 대부분의 시간이 sum_of_lists 내부의 리스트 컴프리헨션 작업에서 소요되었음을 알 수 있습니다. 여기서 얻은 정보를 바탕으로 알고리즘 성능을 높이기 위해 어떤 부분을 수정할지 고민해 볼 수 있습니다.

%prun에 대한 더 자세한 내용은 %prun?을 입력해 도움말을 참고하세요.

%lprun을 사용한 라인별 프로파일링

%prun을 통한 함수 단위 프로파일링도 유용하지만, 때로는 각 코드 줄(line) 단위의 실행 보고서가 필요할 때가 있습니다. 이 기능은 파이썬이나 IPython에 기본 내장되어 있지 않지만, line_profiler 패키지를 설치해 사용합니다. 먼저 파이썬 패키지 관리 도구인 pip를 사용해 패키지를 설치합니다.

$ pip install line_profiler

설치 후 IPython에서 해당 패키지에 포함된 line_profiler 확장 모듈을 불러옵니다.

%load_ext line_profiler

이제 %lprun 명령어로 모든 함수에 대해 라인별 프로파일링을 수행합니다. 이때 어떤 함수를 정밀하게 분석할지 명시적으로 지정해 주어야 합니다.

%lprun -f sum_of_lists sum_of_lists(5000)
Timer unit: 1e-06 s

Total time: 0.014803 s
File: <ipython-input-7-f105717832a2>
Function: sum_of_lists at line 1

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     1                                           def sum_of_lists(N):
     2         1          6.0      6.0      0.0      total = 0
     3         6         13.0      2.2      0.1      for i in range(5):
     4         5      14242.0   2848.4     96.2          L = [j ^ (j >> i) for j in range(N)]
     5         5        541.0    108.2      3.7          total += sum(L)
     6         1          1.0      1.0      0.0      return total

상단에 출력된 정보는 결과를 읽는 데 필요한 기준을 제공합니다. 시간 단위는 마이크로초(µs)이며, 프로그램이 어느 줄에서 가장 많은 시간을 쓰고 있는지 한눈에 확인합니다. 이 정보를 활용해 스크립트의 성능을 개선하고 원하는 사용 사례에 최적화합니다.

%lprun에 대한 자세한 옵션은 %lprun?을 통해 확인하세요.

메모리 사용량 프로파일링: %memit 및 %mprun

성능 측정의 또 다른 중요한 축은 메모리 사용량입니다. 이는 memory_profiler 확장을 사용하여 분석합니다. 마찬가지로 pip를 통해 먼저 설치해 줍니다.

$ pip install memory_profiler

설치가 끝나면 IPython에서 로드합니다.

%load_ext memory_profiler

메모리 프로파일러 확장에는 두 가지 핵심 매직 함수가 있습니다. 바로 %memit(%timeit과 유사한 메모리 측정 제공)과 %mprun(%lprun과 유사한 메모리 측정 제공)입니다. %memit은 다음과 같이 간편하게 사용합니다.

%memit sum_of_lists(1000000)
peak memory: 141.70 MiB, increment: 75.65 MiB

이 함수가 실행되는 동안 약 140MB의 메모리를 사용했음을 알 수 있습니다.

메모리 사용량을 라인별로 분석하려면 %mprun 매직 명령어를 사용합니다. 아쉽게도 이 기능은 노트북 내부에서 직접 정의한 함수가 아니라, 별도의 파일(모듈)에 정의된 함수에서만 작동합니다. 따라서 먼저 %%file 셀 매직을 사용해 sum_of_lists 함수가 포함된 mprun_demo.py라는 모듈 파일을 생성해 보겠습니다. 메모리 측정 결과를 더 명확히 보기 위해 한 줄을 추가했습니다.

%%file mprun_demo.py
def sum_of_lists(N):
    total = 0
    for i in range(5):
        L = [j ^ (j >> i) for j in range(N)]
        total += sum(L)
        del L # L에 대한 참조 제거
    return total
Overwriting mprun_demo.py

이제 새로 만든 모듈에서 함수를 불러와 메모리 프로파일러를 실행합니다.


%mprun -f sum_of_lists sum_of_lists(1000000)
Filename: /Users/jakevdp/github/jakevdp/PythonDataScienceHandbook/notebooks_v2/mprun_demo.py

Line #    Mem usage    Increment  Occurences   Line Contents
============================================================
     1     66.7 MiB     66.7 MiB           1   def sum_of_lists(N):
     2     66.7 MiB      0.0 MiB           1       total = 0
     3     75.1 MiB      8.4 MiB           6       for i in range(5):
     4    105.9 MiB     30.8 MiB     5000015           L = [j ^ (j >> i) for j in range(N)]
     5    109.8 MiB      3.8 MiB           5           total += sum(L)
     6     75.1 MiB    -34.6 MiB           5           del L # remove reference to L
     7     66.9 MiB     -8.2 MiB           1       return total

여기서 Increment 열은 각 코드 줄이 전체 메모리 사용량에 미치는 영향을 나타냅니다. 리스트 L을 생성하고 삭제할 때 메모리 점유율이 약 30MB 정도 변하는 것을 확인합니다. 이 값은 파이썬 인터프리터 자체의 기본 메모리 사용량에 추가되는 값입니다.

%memit과 %mprun에 대한 더 자세한 내용은 도움말 기능을 통해 확인합니다 (예: %memit? 입력).