[성능][업데이트] 로깅 API 성능 테스트(log4j, slf4j 등)

# 테스트 환경
1. jdk1.6.0_23
2. 프로파일링 옵션 : -Xrunhprof:cpu=samples,file=d:/cpu1.txt,depth=3
runhprof 옵션은 jdk 가 제공하는 기본 프로파일링 기능으로 자세한 내용은 "java -Xrunhprof:help" 명령어를 통해 확인할 수 있음
3. 테스트 항목
- StopWatch 를 사용한 메서드 시작과 종료 직전의 시각을 측정
- runhprof 옵션을 통한 cpu 타임 샘플링

# 테스트 케이스 및 테스트 소스와 소요시간(단위 밀리세컨드)
1. 문자열 연산(O), 10만번, slf4j - 5번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 100000; i++) {         LOGGER.info("a" + "b" + "c" + "d");     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 7839, 1170
total time, cpu time : 8288, 1146
total time, cpu time : 8123, 1129
total time, cpu time : 8228, 1180
total time, cpu time : 8093, 1222

2. 문자열 연산(X), 10만번, slf4j - 5번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 100000; i++) {         LOGGER.info("abcd");     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 7854, 1132
total time, cpu time : 7920, 1169
total time, cpu time : 8078, 1226
total time, cpu time : 7931, 1153
total time, cpu time : 8072, 1118

# JDK 가 처리하는 문자열 처리 방식이 나뉘네요.
두분이 댓글 달아주신것처럼 추가로 확인해봤습니다. (2011년1월3일 추가)

1. String 타입의 상수값을 붙이는 처리
"a" + "b" + "c" + "d" => "abcd" 로 변환됨

2. String 타입의 상수값과 변수값을 붙이는 처리
String c = "c";
"a" + "b" + c + "d" => (new StringBuilder("ab")).append(c).append("d").toString() 로 변환됨

3. 로그레벨 체크, 10만번, slf4j - 5번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 100000; i++) {         if (LOGGER.isInfoEnabled()) {         }     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 3, 104
total time, cpu time : 3, 107
total time, cpu time : 4, 103
total time, cpu time : 3, 107
total time, cpu time : 2, 106

4. 로그레벨보다 하위레벨로 로깅(실제로는 찍히지 않는 형태), 10만번, slf4j - 5번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 100000; i++) {         LOGGER.debug("abcd");     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 3, 106
total time, cpu time : 4, 104
total time, cpu time : 3, 105
total time, cpu time : 3, 106
total time, cpu time : 3, 104

5. 문자열 연산(O), 100만번, log4j - 1번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 1000000; i++) {         LOGGER.info("a" + "b" + "c" + "d");     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 74702, 11390

5. 문자열 연산(O), 100만번, slf4j - 1번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 1000000; i++) {         LOGGER.info("{}{}{}{}", new Object[] {"a", "b", "c", "d"});     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 76899, 11532

6. ReflectionToStringBuilder 연산, 10만번, slf4j - 1번 테스트해서 평균 산정

@Test public void test() {     StopWatch watch = new StopWatch();     watch.start();     for (int i = 0; i < 100000; i++) {         LOGGER.debug(ReflectionToStringBuilder.toString(article, ToStringStyle.MULTI_LINE_STYLE));     }     watch.stop();     LOGGER.info(String.valueOf(watch.getTotalTimeMillis())); }

total time, cpu time : 12985, 2656

# ReflectionToStringBuilder.toString() 처리를 해당 모델 클래스의 toString() 을 오버라이딩하면서 처리하는 것으로 배봤습니다. (2011년1월3일 추가)

1. LOGGER.debug(ReflectionToStringBuilder.toString(article)); => 오래걸림
2. LOGGER.debug(article.toString()); => 상동
3. LOGGER.debug("{}", article.toString()); => 상동

4. LOGGER.debug("{}", article); => 로그레벨 체크부터 진행하여, 금방끝남, 즉 4번째 경우처럼 처리해야 실제 성능상의 이점을 볼수 있네요.

5. LOGGER.debug(String.format("%s", scrap)); => log4j 로 바꾸고, String.format 메서드로 처리해봤습니다. 1번 경우보다 2배 정도 걸리네요.

# 평균수치(단위 밀리세컨드)
1. 문자열 연산(O), 10만번, slf4j
total time, cpu time : 8114.2, 1169.4

2. 문자열 연산(X), 10만번, slf4j
total time, cpu time : 7971, 1159.6

3. 로그레벨 체크, 10만번, slf4j
total time, cpu time : 3, 105.4

4. 로그레벨보다 하위레벨로 로깅(실제로는 찍히지 않는 형태), 10만번, slf4j
total time, cpu time : 3.2, 105

5. 문자열 연산(O), 100만번, log4j
total time, cpu time : 74702, 11390

5. 문자열 연산(O), 100만번, slf4j
total time, cpu time : 76899, 11532

6. ReflectionToStringBuilder 연산, 10만번, slf4j
total time, cpu time : 12985, 2656

# 정리
- 1, 2번 경우를 볼때, 문자열 연산으로 인한 차이(8114, 7971)가 크지 않은 것 같다.

- 1, 2번 경우는 JDK 컴파일 과정의 최적화 작업으로 성능테스트 결과 차이가 없다.

- Logger로 찍어주는 문자열 자체가 연산에 의해 생성될 경우 LOGGER.isInfoEnabled() 형태로 체크하는 것이 성능상 좋을 수 있다.
- Logger로 찍어주는 문자열 자체가 특별한 연산에 의해 생성되는 경우가 아닐 경우, Logger 자체가 로그 레벨 체크 후 로깅 여부를 판단하는데 LOGGER.isInfoEnabled() 형태로 체크하지 않아도 특별한 성능상의 차이가 발생하지 않을 것으로 보인다.
- 5, 6번 경우를 볼때, log4j와 slf4j의 성능차가 크다고 보기는 어렵다.

- ReflectionToStringBuilder.toString() 처럼 문자열을 생성하는 연산의 비용이 클 경우 LOGGER.isInfoEnabled() 를 사용해서 체크하거나 해당 모델 클래스의 toString을 오버라이드 하고 slf4j 의 파라미터 인자로 처리하면 성능의 이점이 있다.