분류

2019년 1월 25일 금요일

log4j 로그 레벨에 의한 데이터 입출력 시간 실험

이 문서는 tomcat 서버 혹은 JEUS 서버에서 나타나는 대용량 파일에 대한 (3.78GB, 약2500만 로우의 데이터가 수록된) 데이터베이스 적재 작업에서 발생한 성능 저하 현상이 발생해 해당 작업에 로거가 미치는 영향을 정확한 결과로 기록하기 위해 수행하였습니다.

1. log4j 간략정보

아파치의 오픈소스 도구라고 합니다. JAVA기반이기에 웹/와스 기반의 시스템에서 많이 사용합니다. C와 PYTHON등 다양한 언어를 지원한다고 합니다.  프레임워크에 라이브러리로 참조 되는 경우가 많고 환경설정은 대체로 log4j.xml 혹은 log4j2.xml 파일을 통해 로거레벨을 설정하고 있습니다. 로깅 수준에 따라 등록된 다양한 로그들을 유형별로 보여주거나, 숨길 수 있습니다.

로거 레벨에 대한 정보는 아래와 같습니다.
인용 : https://www.tutorialspoint.com/log4j/ 

LevelDescription
ALL사용자 정의를 포함한 모든 레벨 
DEBUG응용 프로그램 수정에 필요한 세부 정보를 지정 
INFO응용 프로그램 진행에 해당하는 정보를 굵은 글씨로 강조하여 지정
WARN잠재적 유해 사항을 지정
ERROR응용 프로그램 진행에는 영향이 없으나, 악영향을 줄 수 있는 오류를 지정
FATAL프로그램 중단이 예상되는 치명적인 오류를 지정 
OFF로그를 해제 
TRACE디버그 보다 상세한 이벤트 정보를 지정

2. 로거 성능 테스트 환경

사용 pc환경 :
프로세서 : Intel(R) Core(TM) i5-3230M@2.60Ghz
설치된 메모리: 8.0GB ddr3
os : windows 7 64bit

대상파일 :
출처 : http://data.imf.org   > Download Imf Data > InterNational Financial Statistics (IFS)
용량 : 3.78GB
행수 : 25,691,217

데이터 추출용 프로그램은 자작으로  4개의 멀티 스레드를 사용하며 jdbc의 array parsing 을 이용한 인서트 작업을 수행합니다. 전체 데이터를 넣는데 1시간이 걸리므로 약 400건씩 데이터를 쪼개 넣는 작업을 1000회 수행 후 종료하도록 한 후 소요시간을 체크해보았습니다.

3. LEVEL에 따른 성능 측정 


Level총 수행정보
ALL224초  입력 - 총 : 312843, 분당 : 83797, 초당: 1396
DEBUG222초  입력 - 총 : 312843, 분당 : 84552, 초당: 1409 
INFO101초  입력 - 총 : 312843, 분당 :185847, 초당: 3097
WARN101초  입력 - 총 : 312843, 분당 : 185847, 초당: 3097 
ERROR97초  입력 - 총 : 312843, 분당 : 191536, 초당 : 3192
FATAL100초  입력 - 총 : 312843, 분당 : 187705, 초당 : 3128
OFF104초  입력 - 총 : 312843, 분당 : 180486, 초당 3008 
TRACE226초  입력 - 총 : 312843, 분당 : 83055, 초당 1384
각각 1회씩 수행한 결과입니다. off만 예측과 너무 다른 결과가 나와서 3회 수행하였습니다. 하지만 3회 모두 유사한 결과가 도출되었습니다.

처리속도에 연관되는 debugger level 별 성능 순위는 아래와 같습니다.
성능은 초당 입력 건수를 기준으로 상승률을 %로 뽑아봤습니다.

1위 ERROR                    :  5위 대비 130% 성능 상승
2위 FATAL                     :  5위 대비 126% 성능 상승
3위 OFF                        :  5위 대비 123% 성능 상승
4위 INFO, WARN             :  5위 대비    7% 성능 상승
5위 ALL, DEBUG, TRACE   

운영 시스템의 성능 최적화를 위한 로거 레벨은 ERROR, FATAL을 사용하는 것이 나은 것 같습니다. OFF의 성능이 생각보다 낮은 이유는... 언젠가 알고 싶네요 ㅎㅎ;

4. 기타 

최근 사무실에서 사람들이 SQL오류를 확인하기 위해서 core.log.jdbc.driver.OracleDriver 라는 드라이버 클래스를 사용하기 시작했습니다. 줄 바꿈과 파라미터 인풋을 지원하는 드라이버 클래스인데 개발자 중 일부가 이것을 운영 서버에 적용하면서 어마어마한 일이 일어났었습니다. 파일 적재 시스템 마비가 왔었죠.... 약 3천만 건 처리 예상 시간이 21일 16시간이었습니다. ;

일상적으로 사용하는 oracle 용 jdbc드라이버 클래스는 oracle.jdbc.driver.OracleDriver인데 상위 드라이버를 사용할 시 로거 레벨과 관계없이 속도가 저하됩니다. CPU와 메모리의 사용율도 100%가 유지되며, 시스템의 각 기능이 정상동작하지 않게 됩니다.

core.log.jdbc.driver.OracleDriver의 성능

경과시간 1950초 총 입력 건수 23108건, 분당입력 710, 초당입력 11건

1000번은커녕 77회 수행 후 종료해야 했습니다. 저도 일은 해야 하니까요 ㅎㅎ;;;

1위 대비 29018% 성능 저하

이 정도면 사람 하나 죽어나갈 속도입니다. 부디 운영 중인 시스템에 이런 로그 클래스를 사용하는 일이 없으시길 바랍니다.

이상 log4j에 대한 간결한 시험기였습니다. 읽어주셔서 감사합니다. 행복하세요 ㅎㅎ


댓글 없음:

댓글 쓰기