파이썬 프로그램의 병목/정체 구간 찾기, 프로파일러 사용하기

파이썬 프로그래밍의 장점 중의 하나라면 다양한 라이브러리가 공개되어 있어 필요에 따라 적절하게 설치해서 손쉽게 활용할 수 있는 것이다. 그렇지만, 내가 직접 개발한 것이 아닌 블랙박스와 같은 것이므로 라이브러리에서 문제가 생기면 황당할 수밖에 없다. 필자가 경험한 사례는 다른 옵션을 사용할 때는 문제가 없던 프로그램이 gevent 라이브러리를 사용하는 웹서버를 가동하면 위의 그림처럼 CPU 사용도가 급격하게 올라가는 것이었다. 클라이언트 요청이 많아서 웹서버가 할 일이 많았다면 그럴 수도 있겠다 싶지만, 현재 상황은 아무런 요청도 없는 상태로 CPU 로드가 올라갈 이유가 없다. CPU 로드를 엄청 먹고 있는 프로세스의 PID를 메모한다.

 

(volttron) ubuntu@ubuntu:~/volttron$ pip list | grep ws
ws4py                0.5.1
(volttron) ubuntu@ubuntu:~/volttron$ pip check ws4py
No broken requirements found.
(volttron) ubuntu@ubuntu:~/volttron$ pip list | grep gevent
gevent               21.12.0
watchdog-gevent      0.1.1
(volttron) ubuntu@ubuntu:~/volttron$ pip check gevent
No broken requirements found.

일단 사용하는 파이썬 라이브러리들의 버전과 연관 도구들이 제대로 설치되어 있는지를 위의 예제처럼 pip list, pip check 명령으로 확인한다.

 

pip install py-spy

패키지 설치에 별 문제가 없다면 대체 코드의 어디에서 문제가 있는 것인지를 찾아야 할 텐데 이런 경우 등장하는 것이 프로파일러이다. 프로그램 수행과정에서 가장 많은 호출이 있었던 병목 구간 내지 정체 구간을 찾는 것이다. 지금 글에서는 대체 어디에서 CPU를 먹고 있는지 찾아서 라이브러리 사용법을 바꾸거나 라이브러리 자체를 바꾸려는 의도이지만 장시간 시스템에 상주하며 서비스하는 대몬 성격의 프로그램들은 프로파일링을 통해서 어떤 구간에 대한 성능 개선을 수행할지 전략을 수립하는데 많은 도움을 받을 수 있다. 파이썬 프로그램은 "py-spy" 패키지를 통해서 간편하게 프로파일링을 수행할 수 있다. 위의 예제처럼 pip 명령으로 py-spy를 설치한다.

 

(volttron) ubuntu@ubuntu:~/volttron$ py-spy record --pid 24181
Permission Denied: Try running again with elevated permissions by going 'sudo env "PATH=$PATH" !!'
(volttron) ubuntu@ubuntu:~/volttron$ sudo env "PATH=$PATH" py-spy record --pid 24181
[sudo] password for ubuntu:
py-spy> Sampling process 100 times a second. Press Control-C to exit.

py-spy> 1.01s behind in sampling, results may be inaccurate. Try reducing the sampling rate
py-spy> 1.02s behind in sampling, results may be inaccurate. Try reducing the sampling rate
py-spy> 1.08s behind in sampling, results may be inaccurate. Try reducing the sampling rate
py-spy> 1.03s behind in sampling, results may be inaccurate. Try reducing the sampling rate
py-spy> 1.08s behind in sampling, results may be inaccurate. Try reducing the sampling rate
py-spy> 1.15s behind in sampling, results may be inaccurate. Try reducing the sampling rate
^C
py-spy> Stopped sampling because Control-C pressed
py-spy> Wrote flamegraph data to '24181-2023-09-05T16:21:12+09:00.svg'. Samples: 6421 Errors: 0

크지 않고 단순한 프로그램이라면 "py-spy record python sampleprg.py"처럼 프로그램의 시작부터 프로파일링을 수행할 수 있지만, 이번 사례는 프로그램의 시작 과정이 복잡하고 살행 중의 특정 상태를 확인하기 위한 것이므로 앞서 top 도구로 메모한 프로세스의 PID를 가지고 위의 예제 "py-spy record --pid 24181"처럼 PID를 통해서 실행 중인 프로세스를 직접 프로파일링 한다. 권한이 없다는 경고가 나오면 경고 메시지에 있는 것처럼 앞에 sudo env "PATH=$PATH"를 붙여 주면 정상적으로 수행할 수 있다. py-spy 수행 후에 몇 초간 기다린 다음에 Ctrl+C 키로 샘플링 작업을 중단시키면 위의 예제처럼 *. svg 파일로 분석 결과를 자동으로 생성한다. 벡터 그래픽 파일이므로 웹브라우저에서 열어 볼 수 있다.

 

위의 생성된 *.svg 파일이다. 프레임그래프에서 바가 가장 큰 하부 영역이 CPU를 붙잡고 있는 것이므로 해당 부분을 집중적으로 정리하면 된다. 마우스를 바에 올리면 해당 코드와 점유율을 구체적으로 확인할 수 있다. 웹브라우저에서 확대 보기로 해도 좋다. 분석해 보니 gevent나 ws4py같은 외부 패키지가 아니라 응용 프로그램 부분에서 CPU를 먹고 있었다. 사용자 프로그램에서 문제나 병목이 있다면 직접 손댈 수 있으니 다행이다. 이렇게 py-spy와의 첫 만남을 갖는다.