지난 며칠 동안 모 모바일 게임의 알파테스트가 있었다. 그리고 갑이 뽑아달라는 ad-hoc 통계를 뽑느라 로그 처리를 왕창 할 일이 있었다.
대략,
- 로그 데이터는 하나의 JSON 문서로, 각 파일에 한 줄씩 차지하고 있다
- 파일은 날짜 별로 쪼개져서 서버 로그 디렉터리에 남아있다
내부 테스트나 첫날 정도까지는 로그 처리가 순식간에 끝날 수준이라 (k초 수준; k < 10) 별로 신경 안 썼는데, 막상 데이터가 커지기 시작하니 오래 걸리기 시작. (오래 걸린다 == 실행하고 결과 나올 때까지 걸리는 시간이 내 집중력이 유지되는 시간보다 길다) 그리고 ad-hoc 통계를 뽑으려다 보니 내가 실행하는 횟수가 계속 늘어서 걸리는 시간 줄이려고 삽질한 기록이 아래와 같다.
진행
대략 로그가 1 GiB 정도 쌓인 시점에서, 로그 처리를 완료하고 통계 데이터가 나올 때까지 55초 정도 걸리더라. (i7-2600 / 메모리 16 GiB / 샘숭 840pro) 일단 아래 두 가지로 급한 불은 껐고, 알파테스트가 끝나갈 때야 왜 빨라졌는지 알게 되었다.
일단 PyPy 를 끼얹어 본다.
메모리야 남아돌고, CPU가 100%로 튀는 상황이니 일단 PyPy 를 가져다가 써봤다. Ubuntu 14.04 에는 PyPy 2.2.1 이 있다. 이걸 설치하고 동작하니 대략 33초까지 줄더라. (40% 향상)
최신 버전 릴리즈되는 PPA가 없나 검색해보니, 있더라: PyPy team. 여기서 PyPy 4.0.1을 가져다 쓰면 28초까지 실행 시간이 줄어들더라. (49% 향상)
mmap 도 끼얹어 봅니다.
이전에 하재승 군이 mmap 언급했던 게 생각나서 적용해보았다.
조금 더 빨라진다. 이젠 23초 수준.
여하튼 이 상태로 알파테스트 종료까지 갔더니 대략 로그 2GiB 처리하는데 53~55초 수준. 아마 처음 상태로 끝까지 갔으면 (끝나는 날 오후에도 갑이 통계 추가해달랬으니..) 내 멘탈은 더욱더 남아나지 않았을 듯.
왜 빨라졌는가
왜 빨라졌는지 파악 하지 못하고 있었으니 측정해보자. vmprof 프로파일러 를 붙여서 돌려봤다. (2:20 소요)
loads 밑 그 하위 함수들 (decode, raw_decode) 들에서 잔뜩 시간을 쓰고 있다. 즉, 대부분의 시간을 JSON 디코딩하는데 쓰고 있다는 소리 (json.loads 함수라서)
PyPy 로 구동한건 다음과 같다. 0:55 소요.
작은 루프를 계속해서 돌기 때문인지 대부분의 구간이 JIT 번역된 코드를 실행하고 있다. 여기서도 json.loads 호출의 비율이 크지만 Python 2.7 보다는 그 비율이 낮다.
왜 JSON 성능이 PyPy 쪽이 좋은지 확인해보니 PyPy 2.2.0 릴리즈 노트에 그런 내용이 있더란.
JSON decoding is now very fast (JSON encoding was already very fast)
근데 JSON 성능은 (보통은?) 외부 C library 에 의존해서 성능을 올린 경우가 많다. 그래서 전통의(?) simplejson 과 ujson 을 붙여서 테스트해봤다.
simplejson 으론 성능 향상이 없더라. (PyPy 의 경우 오히려 느려졌다)
C기반 JSON 구현체의 python 바인딩인 ujson 을 시도해봤다.
… ujson C 코드 디버깅 심볼이 없어서인지 제대로 프로파일링 안된 것 같긴한데, 같은 Python 2.7이면서도 시간은 대폭 줄었다. 1:19. (거의 절반) 그래도 통계 데이터를 실제로 해석하는 작은 루프들 성능이 JIT 쪽이 나은지 전체 시간은 여전히 PyPy 쪽이 더 좋다.
요약
- vmprof 좋아요 씁시다.
- Python 표준 라이브러리의 JSON은 너무 느리다. CPython을 써야한다면 ujson, 그게 아니면 PyPy 쓰자.