프로파일링 (4) - line_profiler

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

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

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

---

 

line_profiler

cProfile 모듈은 표준 라이브러리에 내장된 프로파일링 도구로 함수 단위로 병목을 찾아줄 수 있는 매우 편리한 도구지만 해당 함수 블록 안에서 line by line 단위의 프로파일링은 해줄 수 없습니다. 이때 사용할 수 있는 강력한 도구가 로버트 컨 (Robert Kern) 이 개발한 line_profiler 입니다. 

pip install line_profiler

 

위 명령어를 이용해 line_profiler를 설치하고 cProfile로 가장 큰 병목이 걸렸던 "calculate_z" 함수에 @profiler 데코레이터를 추가합니다. (해당 파일에 별다른 import 없이 데코레이터 추가가 가능합니다) 이후 다음과 같이 kernprof 명령어로 코드를 실행합니다

kernprof -l -v julia.py

• kernprof 는 @profile 데코레이터로 선택한 함수에 대해 line 별로 CPU 시간 든 통계를 기록하는데 사용합니다. line_profiler 패키지를 설치하면 사용 가능합니다.
• "-l" 옵션은 함수 단위가 아니라 한 줄씩 프로파일하겠다는 옵션이며, -v 옵션은 출력 결과를 자세하게 보여줍니다. 

 

실행 결과

Total time: 42.7706 s
File: julia.py
Function: calculate_z at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def calculate_z(maxiter, zs, cs):
     8         1       3463.5   3463.5      0.0      output = [0] * len(zs)
     9   1000001     311307.3      0.3      0.7      for i in range(len(zs)):
    10   1000000     300498.8      0.3      0.7          n = 0
    11   1000000     347609.1      0.3      0.8          z = zs[i]
    12   1000000     326589.9      0.3      0.8          c = cs[i]
    13  34219980   17100987.4      0.5     40.0          while abs(z) < 2 and n < maxiter:
    14  33219980   12665032.2      0.4     29.6              z = z*z + c
    15  33219980   11368682.4      0.3     26.6              n += 1
    16   1000000     346459.4      0.3      0.8          output[i] = n
    17         1          8.7      8.7      0.0      return output

 

보다시피 line 별로 분석이 가능한대신 실행시간이 매우 늘어났습니다. % Time 열 항목을 보면 while 문의 조건 문에서 40%로 제일 많은 시간이 소요된 것을 알 수 있습니다. 또한, while 문 안의 $z,n$을 갱신하는 데도 꽤 많은 시간을 소비했습니다. 이는 파이썬의 동적 시스템으로 인한 결과로 우리가 같은 타입의 변수를 사용해도 계속 1) $n$ 객체의 "__add__" 함수가 있는지 확인하고 2) 다른 객체 (여기서는 1)가 전달됐는지 검사해서 "__add__" 함수가 어떤 식으로 연산을 계산할 지를 결정하는 과정을 반복하기 때문입니다. (이렇게 하는 이유는 다른 객체가 float 일 수도 있고 "__add__" 함수를 적용할 수 없는 다른 형태의 객체일 수도 있기 때문입니다) 

 

while 조건 분석

while 문의 두 가지 조건 1) "abs(z) < 2", 2) "n < maxiter" 중 어느 조건이 시간이 더 걸리는 지 분석하기 위해 두 조건을 나눠보도록 하겠습니다. 

Total time: 69.1226 s
File: julia.py
Function: calculate_z at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def calculate_z(maxiter, zs, cs):
     8         1       3881.5   3881.5      0.0      output = [0] * len(zs)
     9   1000001     331965.6      0.3      0.5      for i in range(len(zs)):
    10   1000000     317628.5      0.3      0.5          n = 0
    11   1000000     367167.4      0.4      0.5          z = zs[i]
    12   1000000     343283.7      0.3      0.5          c = cs[i]
    13                                                   while True:
    14  34219980   17216460.5      0.5     24.9              not_yet_escaped = abs(z) < 2
    15  34219980   12539573.9      0.4     18.1              iteration_left = n < maxiter
    16  34219980   11794453.1      0.3     17.1              if not_yet_escaped and iteration_left:
    17  33219980   13775615.6      0.4     19.9                  z = z*z + c
    18  33219980   12065575.8      0.4     17.5                  n += 1
    19                                                       else:
    20                                                           break
    21   1000000     367013.1      0.4      0.5          output[i] = n
    22         1          8.4      8.4      0.0      return output

 

이전 버전에 비해 시간이 더 걸렸는데, 이는 새로 추가한 코드를 33219980 회 더 실행했기 때문입니다. while 문 두 가지 조건에 걸리는 시간을 보면 "abs(z) < 2" 조건이 "n < maxiter" 에 비해 더 오래 걸립니다. 이를 간단히 확인해보면, $n$값을 검사하는 코드가 $abs$를 호출하는 코드보다 거의 2배가 빠른 것을 볼 수 있습니다.

z = 0+0j
%timeit abs(z) < 2
125 ns ± 3.82 ns per loop (mean ± std. dev. of 7 runs, 1000000 loops each)

n = 1
maxiter = 300
%timeit n < maxiter
64.2 ns ± 0.641 ns per loop (mean ± std. dev. of 7 runs, 10000000 loops each)

 

파이썬은 문장을 왼쪽에서 오른쪽으로 검사하며, 파이썬의 and 구문은 왼쪽 조건이 False 이면 오른쪽 조건을 검사하지 않고 지나치기 때문에 빨리 끝나는 간단한 조건을 왼쪽에 두는 것이 더 좋다고 생각할 수 있습니다. 또한, "abs(z)  < 2"는 $z$의 절대값을 계산하기 전까지는 알 수 없고 대략 10%의 $z$ 만이 이 조건을 만족하기 때문에 이 조건은 오른쪽에 두는 것이 더 유리합니다. 따라서 원래 while 문 두 조건의 위치를 변경하고 프로파일링을 다시 해보겠습니다.

Total time: 44.9835 s
File: julia.py
Function: calculate_z at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def calculate_z(maxiter, zs, cs):
     8         1       5315.9   5315.9      0.0      output = [0] * len(zs)
     9   1000001     324715.4      0.3      0.7      for i in range(len(zs)):
    10   1000000     313187.5      0.3      0.7          n = 0
    11   1000000     361323.4      0.4      0.8          z = zs[i]
    12   1000000     337847.9      0.3      0.8          c = cs[i]
    13  34219980   18033423.2      0.5     40.1          while n < maxiter and abs(z) < 2:
    14  33219980   13328828.4      0.4     29.6              z = z*z + c
    15  33219980   11919420.2      0.4     26.5              n += 1
    16   1000000     359401.2      0.4      0.8          output[i] = n
    17         1          6.7      6.7      0.0      return output

• 하지만 프로파일 결과 상으로는 큰 개선은 없네요. 실행시간이 약간 짧아졌습니다.

 

전체 코드 분석 

"calculate_julia" 전체 함수에 대해 분석한 결과입니다. 예상대로 "calculate_z" 함수가 실행 시간의 93.5%를 차지하네요. line_profiler 는 오버헤드가 매우 크지만 각 줄의 실행 비용을 계산할 수 있다는 점에서 매우 효과적인 프로파일링 도구입니다. (Total time 이 오히려 덜 걸리는데, 이는 "calculate_z" 함수에서 @profile 데코레이터를 빼서 "calculate_z" 함수 라인 별 분석에 따른 오버헤드가 없었기 때문입니다. 실제로 "calculate_z" 함수에서도 @profile 데코레이터를 달게 되면 Total time이 80초가 넘어가게 됩니다)

Total time: 35.2221 s
File: julia.py
Function: calculate_julia at line 19

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    19                                           @profile
    20                                           def calculate_julia(desired_width=1000, maxiter=300):
    21         1          1.8      1.8      0.0      x_step = (x2 - x1) / desired_width
    22         1          0.8      0.8      0.0      y_step = (y1 - y2) / desired_width
    23
    24         1          0.5      0.5      0.0      x = []
    25         1          0.4      0.4      0.0      x_coord = x1
    26      1001        432.4      0.4      0.0      while x_coord < x2:
    27      1000        448.9      0.4      0.0          x.append(x_coord)
    28      1000        387.6      0.4      0.0          x_coord += x_step
    29         1          0.5      0.5      0.0      y = []
    30         1          0.5      0.5      0.0      y_coord = y2
    31      1001        407.2      0.4      0.0      while y_coord > y1:
    32      1000        452.9      0.5      0.0          y.append(y_coord)
    33      1000        395.6      0.4      0.0          y_coord += y_step
    34
    35         1          0.4      0.4      0.0      zs = []
    36         1          0.4      0.4      0.0      cs = []
    37      1001        669.2      0.7      0.0      for ycoord in y:
    38   1001000     531281.3      0.5      1.5          for xcoord in x:
    39   1000000     880277.1      0.9      2.5              zs.append(complex(xcoord, ycoord))
    40   1000000     880193.0      0.9      2.5              cs.append(complex(c_real, c_img))
    41
    42         1        211.9    211.9      0.0      print(f"Total elements: {len(zs)}")
    43         1         16.3     16.3      0.0      start_time = time.time()
    44         1   32926377.2 32926377.2     93.5      output = calculate_z(maxiter, zs, cs)
    45         1          4.3      4.3      0.0      end_time = time.time()
    46         1          1.0      1.0      0.0      elapsed = end_time - start_time
    47         1        490.4    490.4      0.0      print(calculate_z.__name__, f" took {elapsed} seconds")
    48         1          1.7      1.7      0.0      return output

 

---

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