반응형
Introduction
- Python으로 짜인 Code를 서비스하다 보면, CPU 100%나 Memory Fault, 실행시간이 길어지는 등 다양한 문제를 만나게 된다.
- 자신이 개발한 코드에서는 직감적으로 어느 부분이 문제가 될지를 간파할 수 있지만, 다른 사람이 짠 코드에서 문제에 원인이 되는 부분을 찾아내기는 매우 어렵다.
- 일반적으로 가장 쉽게 떠올릴수 있는 방법은 실행시간은 time 모듈을 이용한 print 디버깅이나 unittest, CPU나 memory는 작업 관리자를 통해 확인하는 방법이다. 하지만, 이 방법들은 대략적인 정도만 알아낼 수 있고, 어느 부분이 문제가 있는지 진단하기 매우 어렵다.
- Python에서는 Profiling을 위한 다양한 도구들을 가지고 있어, code 분석이 매우 용이하다. 어떤 것들이 있는지 확인해보자!
Code Sample
- 각 도구들을 Test 하기 위한 sample code이다.
- code는 각각 validation_check, data_preprocessing, outlier_remove, data_sort, data_cal_half_avg 함수를 거쳐 최종 결과를 내도록 되어있다.
import numpy as np
def data_validation_check(sensor_value):
try:
for i in sensor_value.split("|"):
float(i)
return True
except:
print("Error")
return False
def data_preprocessing(sensor_value):
sensor_value = sensor_value.split("|")
sensor_value = list(map(float, sensor_value))
return sensor_value
def outlier_remove(sensor_value):
data_mean = np.mean(sensor_value)
data_std = np.std(sensor_value)
lower_bound = data_mean - 3 * data_std
upper_bound = data_mean + 3 * data_std
sensor_value = [i for i in sensor_value if lower_bound < i and upper_bound > i]
return sensor_value
def data_sort(sensor_value):
return np.sort(sensor_value)
def data_cal_half_avg(sensor_value):
return np.mean(sensor_value[int(len(sensor_value) * 0.5):])
def run(sensor_value):
if data_validation_check(sensor_value):
sensor_value = data_preprocessing(sensor_value)
sensor_value = outlier_remove(sensor_value)
sensor_value = data_sort(sensor_value)
sol = data_cal_half_avg(sensor_value)
return sol
else:
return "Error!"
if __name__ == '__main__':
sensor_value = "|".join([str(i) for i in range(10000000)])
print(run(sensor_value))
memory_profiler : Memory Profiling
- Python은 머신러닝 같은 데이터 처리를 위한 언어로 자주 사용되기 때문에, 메모리 관련된 이슈에 자주 직면하게 된다.
- 따라서, 어느 부분이 memory를 많이 소모하는지 확인이 필요한 경우가 많다.
- Python에서는 "memory_profiler"를 통해 memory 사용량을 측정할 수 있다.
[설치 방법]
- 설치 방법은 매우 간단하다. pip을 이용하여 설치한다.
pip install memory_profiler[사용 방법]
- 사용 방법도 매우 간단하다. memory_profiler의 profiler을 import 하고, memory profiling을 하고자 하는 함수에 "@profiler" 데코레이터를 사용하고, 프로그램을 실행하면 끝난다.
[사용 예시]
from memory_profiler import profile
import numpy as np
@profile
def data_validation_check(sensor_value):
try:
for i in sensor_value.split("|"):
float(i)
return True
except:
print("Error")
return False
...
[결과]
- 결과는 다음과 같이, 테이블 형태로 터미널에 출력된다.
- 각 칼럼은 다음을 의미한다.
- Line # : code 내 몇 번째 줄인 지
- Mem Usage : 해당 라인이 실행되기 전의 메모리 사용량
- Increment : 해당 라인의 실행으로 추가적으로 사용된 메모리의 양
- Occurrences : 각 라인이 실행된 횟수
- Line Contents : 라인 코드 내용
- 즉, memory profiler는 각 라인이 수행되기 전과 후를 스냅숏으로 메모리의 증분값을 보여주어, memory 사용량을 나타낸다. (따라서, memory를 해제하는 경우 등에는 음수값이 나올 수 있다.)
- memory_profiler의 결과를 file 형태로 저장하기 위해서는, logger를 사용하거나, 아래와 같이 프로그램 수행 결과를 txt 형태로 내리도록 하면 된다.
python -m memory_profiler main.py > log.txt- memory_profiler를 run 한 후, 아래 명령어로 그래프를 그릴 수 있는데, 사실 이 그래프로 뭘 알 수 있는지는 의문이다. (그냥 시간에 따른 메모리 사용량만 표시된다.)
mprof plot -o memory_profiler_result.png
[Sample 수행 결과]
| ... Filename: main.py Line # Mem usage Increment Occurrences Line Contents ============================================================= 14 118.7 MiB 118.7 MiB 1 @profile 15 def data_preprocessing(sensor_value): 16 807.1 MiB 688.3 MiB 1 sensor_value = sensor_value.split("|") 17 501.2 MiB -305.8 MiB 1 sensor_value = list(map(float, sensor_value)) 18 19 501.2 MiB 0.0 MiB 1 return sensor_value Filename: main.py Line # Mem usage Increment Occurrences Line Contents ============================================================= 21 501.2 MiB 501.2 MiB 1 @profile 22 def outlier_remove(sensor_value): 23 501.3 MiB 0.1 MiB 1 data_mean = np.mean(sensor_value) 24 501.3 MiB 0.0 MiB 1 data_std = np.std(sensor_value) 25 26 501.3 MiB 0.0 MiB 1 lower_bound = data_mean - 3 * data_std 27 501.3 MiB 0.0 MiB 1 upper_bound = data_mean + 3 * data_std 28 29 579.9 MiB 78.5 MiB 10000003 sensor_value = [i for i in sensor_value if lower_bound < i and upper_bound > i] 30 579.9 MiB 0.0 MiB 1 return sensor_value Filename: main.py Line # Mem usage Increment Occurrences Line Contents ============================================================= 32 503.5 MiB 503.5 MiB 1 @profile 33 def data_sort(sensor_value): 34 579.9 MiB 76.3 MiB 1 return np.sort(sensor_value) Filename: main.py Line # Mem usage Increment Occurrences Line Contents ============================================================= 36 197.5 MiB 197.5 MiB 1 @profile 37 def data_cal_half_avg(sensor_value): 38 197.5 MiB 0.0 MiB 1 return np.mean(sensor_value[int(len(sensor_value) * 0.5):]) 7499999.5 mprof: Sampling memory every 0.1s running new process running as a Python program... |
- 사실, 언뜻 생각하기엔 sort에서 가장 많은 memory가 사용될 것이라고 생각했지만, 의외로 outlier 제거를 위한 순회나, split등에서 많이 사용된다는 것을 알 수 있다.
[주의점]
- memory의 profile은 memory의 snapshot과 기록에 많은 추가 시간이 소요되기 때문에, memory profile과 실행시간 측정은 동시에 진행하면 안 된다.
- memory가 snapshot 형태로 기록되기 때문에, memory 소요값이 절대적이지 않고, 실행 환경 등에 따라 다르다는 점을 꼭 기억하자!
Execution Time Profiling : line_profiler
- Execution Time은 Python에서 가장 민감한 부분이기도 하다.
- 보통 time 모듈을 이용하여 디버깅을 진행하기도 하는데, 매구 간마다 디버깅을 위해 시간을 찍는 것도 매우 비효율적이다.
- 이런 비효율을 덜어줄 수 있는 Execution Time profiling 도구 line_profiler이다.
[설치 방법]
- 설치 방법은 memory_profiler처럼 pip을 이용하여 설치한다.
pip install line_profiler[사용 방법]
- 사용 방법은 더 간단하다. 실행 시간을 측정하고 싶은 함수에 "@profile" 데코레이터를 넣어주고, 터미널에서 아래 명령어를 실행해 주면 된다.
kernprof -l -v main.py
[사용 예시]
# memory_profiler가 import 안되도록 한번 더 확인!
import numpy as np
@profile
def data_validation_check(sensor_value):
try:
for i in sensor_value.split("|"):
float(i)
return True
except:
print("Error")
return False
...
[결과]
- 결과는 다음과 같이, 테이블 형태로 터미널에 출력된다.
- 우선 맨 위에, 시간 unit과 각 함수 total 수행 시간이 표시된다. (전체 total 수행 시간이 아니다.)
- 아래 각 칼럼은 다음을 의미한다.
- Line # : code 내 몇 번째 줄인 지
- Hits: 각 라인이 실행된 횟수
- Time : 수행 시간
- Per Hit: 각 실행당 걸린 시간
- % Time : 함수 내 실행 시간에서 차지하는 퍼센트
- Line Contents : 라인 코드 내용
- line_profiler의 결과를 file 형태로 저장하기 위해서는, 아래 명령어를 사용하면 된다. line_profiler를 실행하면, 실행 파일에 대한 lprof의 파일 결과가 떨어지는데, 이를 text 파일로 떨구면 된다.
python -m line_profiler main.py.lprof > log.txt
[Sample 수행 결과]
- 첫 생각과는 다르게, validation check가 가장 많은 시간이 소요되는 것을 확인할 수 있다.
| Timer unit: 1e-06 s Total time: 4.83922 s File: main.py Function: data_validation_check at line 3 Line # Hits Time Per Hit % Time Line Contents ============================================================== 3 @profile 4 def data_validation_check(sensor_value): 5 1 0.5 0.5 0.0 try: 6 10000000 1970775.1 0.2 40.7 for i in sensor_value.split("|"): 7 10000000 2868439.0 0.3 59.3 float(i) 8 1 1.5 1.5 0.0 return True 9 except: 10 print("Error") 11 return False Total time: 1.48381 s File: main.py Function: data_preprocessing at line 13 Line # Hits Time Per Hit % Time Line Contents ============================================================== 13 @profile 14 def data_preprocessing(sensor_value): 15 1 369882.5 369882.5 24.9 sensor_value = sensor_value.split("|") 16 1 1113930.3 1113930.3 75.1 sensor_value = list(map(float, sensor_value)) 17 18 1 1.3 1.3 0.0 return sensor_value Total time: 2.66128 s File: main.py Function: outlier_remove at line 20 Line # Hits Time Per Hit % Time Line Contents ============================================================== 20 @profile 21 def outlier_remove(sensor_value): 22 1 337871.3 337871.3 12.7 data_mean = np.mean(sensor_value) 23 1 366792.1 366792.1 13.8 data_std = np.std(sensor_value) 24 25 1 5.7 5.7 0.0 lower_bound = data_mean - 3 * data_std 26 1 10.6 10.6 0.0 upper_bound = data_mean + 3 * data_std 27 28 1 1956595.8 1956595.8 73.5 sensor_value = [i for i in sensor_value if lower_bound < i and upper_bound > i] 29 1 0.7 0.7 0.0 return sensor_value Total time: 0.415683 s File: main.py Function: data_sort at line 31 Line # Hits Time Per Hit % Time Line Contents ============================================================== 31 @profile 32 def data_sort(sensor_value): 33 1 415683.2 415683.2 100.0 return np.sort(sensor_value) Total time: 0.003097 s File: main.py Function: data_cal_half_avg at line 35 Line # Hits Time Per Hit % Time Line Contents ============================================================== 35 @profile 36 def data_cal_half_avg(sensor_value): 37 1 3097.0 3097.0 100.0 return np.mean(sensor_value[int(len(sensor_value) * 0.5):]) |
[주의점]
- memory profiler와 마찬가지로, line_profiler로 수행시간을 차분하여, 라인 별 수행시간을 구하는 것이다. 따라서, 절대적이지 않고 수행 환경에 따라 달라진다.
Process Profiling : py-spy
- CPU는 운영체제의 스케줄링이나 프로세스 등에 따라 동적으로 변하기 때문에, 함수마다의 수행시간을 정확히 측정하는 것은 매우 어렵다.
- 따라서, CPU는 리눅스 명령어나 윈도 작업관리자를 통해, 프로그램 수행 후 observation 형태로 간접적으로 파악하는 방법 밖에 없다.
- 또한, CPU는 사용량이 많더라도, 조치하기가 매우 어렵다. 따라서, 너무 CPU 사용량이 많은 부분만 확인하는 정도의 이상감지용 지표로 활용하는 것이 좋다.
- CPU 사용률을 직접 측정하기는 어렵지만, 각 Process에 걸리는 부하를 간접적으로 알 수 있는 도구가 있는데, 바로 py-spy이다.
[설치 방법]
- 설치 방법은 앞선 profiler들처럼 pip을 이용하여 설치한다.
pip install py-spi[사용 방법]
- 사용 방법은 단순히 아래 명령어를 터미널에 입력해 주면 된다.
py-spy record -o profile.svg -- python main.py
[결과]
- 결과는 위에서 지정한 profile.svg(이름은 바꿔도 된다.) 파일의 스택 플레임 그래프 형태로 떨어진다.
- 결과는 다음의 형태를 가진다.
- 함수 호출 스택이 위에서부터 바깥쪽의 함수를 의미한다. 예를 들어, 예제의 run 함수 → data_preprocessing 함수 → split 함수 형태로 위부터 아래로 표시된다.
- Box 표시 : 각 함수가 Box로 표시된다. Box의 크기가 해당 함수의 소비 시간을 나타낸다. 따라서, 상위 함수는 하위 여러 함수들의 박스들로 구성된다.
- 색상 : 어두운 색상에 있는 함수일수록 깊은 호출 스택을 의미한다.
- 일반적으로, 다음과 같은 결과 해석이 가능하다.
- 우선 Box가 큰 함수의 부분이 부하의 원인이 되는 경우가 많기 때문에 주목해서 봐야 한다.
- Box가 큰 함수들 중, 호출 스택이 깊은 함수들은 여러 번 중첩되는 경우가 많은데, 이 부분의 중첩을 줄여야 개선이 가능하다.
- 다른 profiler들과 다르게, 내부의 import 된 함수 단위까지 표시가 되기 때문에, 어떤 구조로 함수가 호출되는지 이해가 쉽다.
[주의점]
- 사실, 수행 시간을 통해, 간접적으로 프로세스의 중첩이나, 부하를 확인하는 것이기 때문에, CPU 사용률과 직접적인 연관이 없다. (참고용으로만 사용하는 것이 좋다.)
이 밖에, Python 내장 profiler인 CProfile 같은 Profiler와, Palanteer, Pyinstrument 등의 Profiler 들도 존재한다. 하지만, 프로그램의 수행결과로 논문을 쓸 것이 아니라면, 다음과 같은 툴로도 충분하다고 생각한다.
'Python' 카테고리의 다른 글
| Pandas 성능 향상을 위한 방법들 (2) | 2023.07.21 |
|---|---|
| Transformer Pytorch 구현 (11) | 2023.07.15 |
| Pytorch Profiler Tensorboard로 시각화 (1) | 2023.07.10 |
| Pytorch Resource & 모델 구조 Profiler 도구 (torch profiler) (1) | 2023.07.09 |
| Python 속도 최적화 - NUMBA (1) | 2023.06.08 |