프로파일링 (3) - cProfile 모듈

프로파일링 (1) - 줄리아 집합 (Julia set)

프로파일링 (2) - 함수 실행 시간 계산하기

---

 

Cprofile 모듈이란 ?

cProfile은 표준 라이브러리에 내장된 프로파일링 도구로, C파이썬의 가상 머신 안에서 확인되는 모든 함수에 시간을 측정하는 장치를 연결합니다. 표준 라이브러리에서 제공하는 다른 프로파일러는 순수 파이썬 기반의 profile이 있지만 오버헤드를 줄이기 위해 C로 작성한 cProfile에 비해 현저히 느립니다. cProfile은 line by line 별로 분석하지는 못하지만, 기본 내장된 도구로 편리하고 빠르게 병목 지점을 찾을 수 있습니다.

 

줄리아 집합 프로파일링

지난 포스트에서 작성한 줄리아 집합에 대해 cProfile 모듈을 이용하여 프로파일링 해보곘습니다. 일단 다음 명령어를 통해 각 함수에서 소비한 누적 시간순으로 정렬된 프로파일링 결과를 볼 수 있습니다. (cProfile의 "-s cumulative" 옵션을 기입해야합니다)

python -m cProfile -s cumulative julia.py

Total elements: 1000000
calculate_z  took 13.015206336975098 seconds
         36221992 function calls in 13.775 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   13.775   13.775 {built-in method builtins.exec}
        1    0.037    0.037   13.775   13.775 julia.py:1(<module>)
        1    0.524    0.524   13.738   13.738 julia.py:18(calculate_julia)
        1    7.929    7.929   13.015   13.015 julia.py:6(calculate_z)
 34219980    5.085    0.000    5.085    0.000 {built-in method builtins.abs}
  2002000    0.199    0.000    0.199    0.000 {method 'append' of 'list' objects}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        2    0.000    0.000    0.000    0.000 {built-in method time.time}
        3    0.000    0.000    0.000    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

 

결과 분석

프로파일링 결과에서 ncalls 는 함수 호출 횟수, tottime 은 해당 함수가 소비한 시간, cumtime 은 해당 함수가 call 한 모든 함수가 소비한 누적 시간을 나타냅니다. 먼저 코드 실행은 총 13.775 초가 소비되었는데, 이는 지난 번의 10초보다 3.5초 가량이 증가한 것으로 cProfile이 각 함수가 소비한 시간을 추가로 알아내는데, 3.5초 가량을 더 사용한 것입니다. (프로파일링이다 보니 어쩔 수 없이 오버헤드가 발생합니다)

julia.py 의 첫 번째 줄에서 13.775초를 소비했고 "calculate_julia", "calculate_z" 함수가 각각 한 번씩 실행되었습니다. (ncalls 1) 또한, "calculate_julia" 함수에서 호출한 "calculate_z" 함수가 13.015초를 소비했으므로 "calculate_julia" 함수에서 "calculate_z" 함수를 제외한 부분에서 0.7 초 가량을 소비했다고 유추할 수 있겠죠.

"calculate_z" 함수에서는 abs 함수를 34219980 번 호출하는데 5초 정도를 사용하고 나머지 부분에서는 2.9초 정도를 사용했습니다. abs 함수 한 번의 호출은 무시할 정도로 작지만 34219980 번 호출하니 5초 정도가 소요되는군요. 줄리아 집합의 그리드가 1000x1000 이므로 총 백만 픽셀이 되고 각 픽셀에 대해 최대 300번 반복 계산하므로 (지난 포스트 코드 참고) 최악의 경우 3억 번 호출되어야 하지만 3,400만 번 호출되었으므로 약 10% 수준이라고 볼 수 있습니다. 그리고 리스트의 append 메소드가 2002000 번 호출되었습니다. 이는 zs, cs 가 1000x1000 크기의 리스트이고 이는 1000개의 x/y 좌표에서 만들어지므로 2*(1000*1000) + 2*1000 = 2002000 여서 그렇습니다.

위의 결과를 보면 각 함수 별로 얼마만큼의 시간을 소비하는지 알 수 있지만 이 결과가 부모 함수에 따라 정렬되지 않고 코드 블록 안의 모든 함수가 소비한 시간을 보여주므로 함수 안의 각 줄의 정보를 얻어낼 수는 없습니다. 

 

프로파일링 통계

통계 파일을 생성한 뒤 ("-o 파일명" 옵션을 통해 통계 파일을 저장할 수 있습니다) 파이썬으로 분석해서 cProfile의 결과를 좀 더 세밀하게 살펴볼 수 있습니다. 

python -m cProfile -o profile.stats julia.py

 

다음과 같이 통계 파일을 불러들이면 앞서 본 출력과 동일한 결과를 얻을 수 있습니다.

import pstats
p = pstats.Stats("profile.stats")
p.sort_stats("cumulative")
p.print_stats()

 

또한, 해당 함수를 호출한 측 (caller) 의 정보와 해당 함수에서 호출한 (callee) 함수 정보도 확인할 수 있습니다.

>>> p.print_callers()
   Ordered by: cumulative time

Function                                          was called by...
                                                      ncalls  tottime  cumtime
{built-in method builtins.exec}                   <-
main.py:1(<module>)                               <-       1    0.033   13.377  {built-in method builtins.exec}
main.py:18(calculate_julia)                       <-       1    0.515   13.344  main.py:1(<module>)
main.py:6(calculate_z)                            <-       1    7.741   12.633  main.py:18(calculate_julia)
{built-in method builtins.abs}                    <- 34219980    4.893    4.893  main.py:6(calculate_z)
{method 'append' of 'list' objects}               <- 2002000    0.195    0.195  main.py:18(calculate_julia)
{built-in method builtins.print}                  <-       2    0.001    0.001  main.py:18(calculate_julia)
{built-in method time.time}                       <-       2    0.000    0.000  main.py:18(calculate_julia)
{method 'disable' of '_lsprof.Profiler' objects}  <-
{built-in method builtins.len}                    <-       2    0.000    0.000  main.py:6(calculate_z)
                                                           1    0.000    0.000  main.py:18(calculate_julia)

---

>>> p.print_callees()
   Ordered by: cumulative time

Function                                          called...
                                                      ncalls  tottime  cumtime
{built-in method builtins.exec}                   ->       1    0.033   13.377  main.py:1(<module>)
main.py:1(<module>)                               ->       1    0.515   13.344  main.py:18(calculate_julia)
main.py:18(calculate_julia)                       ->       1    7.741   12.633  main.py:6(calculate_z)
                                                           1    0.000    0.000  {built-in method builtins.len}
                                                           2    0.001    0.001  {built-in method builtins.print}
                                                           2    0.000    0.000  {built-in method time.time}
                                                     2002000    0.195    0.195  {method 'append' of 'list' objects}
main.py:6(calculate_z)                            -> 34219980    4.893    4.893  {built-in method builtins.abs}
                                                           2    0.000    0.000  {built-in method builtins.len}
{built-in method builtins.abs}                    ->
{method 'append' of 'list' objects}               ->
{built-in method builtins.print}                  ->
{built-in method time.time}                       ->
{method 'disable' of '_lsprof.Profiler' objects}  ->
{built-in method builtins.len}                    ->

 

---

프로파일링 (4) - line_profiler

프로파일링 (5) - 바이트코드: 내부작동 이해하기