달력

112018  이전 다음

  •  
  •  
  •  
  •  
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27
  • 28
  • 29
  • 30
  •  
SpringJDBC를 사용할때, PreparedStatement 의 파라미터를 로그에 찍기 위해서는 로그레벨을 TRACE로 해야 한다.

<logger name="org.springframework.jdbc.core" additivity="false">
    <level value="TRACE" />
    <appender-ref ref="console" />
</logger>

Posted by 이동국

댓글을 달아 주세요

# 테스트 환경
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일 추가)

더보기



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. 문자열 연산(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 의 파라미터 인자로 처리하면 성능의 이점이 있다.

Posted by 이동국

댓글을 달아 주세요

  1. 지나가다  댓글주소 수정/삭제 댓글쓰기 2010.12.30 12:12 신고

    1번과 2번은 의미없는 측정입니다. 컴파일 단계에서 "a" + "b" + "c" + "d" 는 "abcd" 로 변환되어 컴파일 됩니다. 두 로거의 특징이라면 log4j.log("some - " + someObject), slf4j.log("some - {}", someObject) 등의 연산에서 log level 에 따라 실제 로깅하지 않아야 할 연산도 log4j 의 경우 string 으로 변환 후 넘기기 때문에 이에 따른 성능 저하가 있을 수 있습니다. slf4j 는 인자(최대 2개)로 넘어온 값을 Log level 체크 후 string 으로 변환하기 때문에 log level 체크를 지저분하게 하지 않아도 되는 경우에 이점이 있지요. 성능 비교를 하려면 이 두 가지 경우(5번이 여기에 포함되나 다양한 표현식과 데이터 산정이 필요할 듯)가 적합할 듯 싶네요.

    • 이동국  댓글주소 수정/삭제 2010.12.30 23:58 신고

      1. 먼저 1, 2번 비교가 의미가 없지는 않습니다. 컴파일 단계에 "a" + "b" + "c" + "d" 가 "abcd" 가 되는게 아니라 StringBuilder 로 변환 후 append되는 것으로 알고 있습니다. append되는 것과 "abcd"는 상황이 조금 다른거 같습니다.
      2. slf4j의 경우 {} 를 통한 치환이 장점이라고 하지만 log4j도 String의 format 메서드를 사용하면 비슷하게 사용이 가능할 듯 합니다. 게다가 로그 레벨을 info 로 하더라도 LOGGER.debug("{}" + ReflectionToStringBuilder.toString(this, ToStringStyle.MULTI_LINE_STYLE)); 형태로 찍어주면 ReflectionToStringBuilder.toString 처리는 먼저 해버리기 때문에 성능차는 거의 같습니다.
      3. 실제로 성능적인 부분은 확인해보셨는지 의심스럽네요. slf4j를 사용하더라도 인자로 던져주는 메시지를 처리하는 작업이 로그레벨 확인하는 처리보다 먼저 될수 있습니다.

  2. benelog  댓글주소 수정/삭제 댓글쓰기 2011.01.01 01:47 신고

    "a"+"b+"c"와 같이 전부 다 상수이면 "abc"로 최적화 된다고 알고 있고, 전에 직접 역컴파일해서 확인을 해봤었습니다. "a"+ i + "c" 같이 중간에 상수가 아닌 변수가 들어가면 StringBuilder로 바꾸어 주고요. 자세한 내용은 http://benelog.springnote.com/pages/526396 , http://mygeni.tistory.com/75 등에 있고, Java String constant concat 으로 검색하면 비슷한 자료가 많이 나옵니다.

    위의 예에서 String var="b";라고 선언 후 debug( "a" + var + "c")와 debug("{} {} {}", "a",var,"c") 를 비교해봐도 재밌는 결과가 나올 것 같네요.

    그리고 ReflectionToStringBuilder.toString 같은 것도 로그 호출의 외부에서 생성하지 않고, reflect의 대상 클래스 안에서 toString을 override해서 정의하고, debug("{}",article) 같은 형식으로 넘기면 성능손해도 없고, 더 편하지 않을까하는 생각이 듭니다. 다만 같은 클래스에 대한 toString이라도 호출 되는 쪽에 따라서 여러가지 형식으로 하고 싶다면 그런 방식이 적합하지 않을 수도 있겠죠.

    암튼 신경써서 쓰지 않으면 그냥 log4j이든 slf4j를 통한 것이든 다 필요없는 성능낭비가 생기게 할 수 있고, 잘 알고 쓰면 그냥 log4j로도 충분히 성능손해가 없게도 할 수 있지만, slf4j에 손가락을 편하게 해주는 메소드들이 있어서 개인적으로 더 선호하기는 합니다.

  3. benelog  댓글주소 수정/삭제 댓글쓰기 2011.01.01 01:51 신고

    그래서 비밀댓글 풀었습니다 ^^; 저런것도 일일히 다 해보시고 넘 부지런해 보이셔서 부럽습니다 ^^;

  4. 규이  댓글주소 수정/삭제 댓글쓰기 2011.01.05 15:26 신고

    log4j랑 slf4j랑 성능에서는 그다지 차이가 나지 않는다는 말씀이신가요? 수치만 보고 판단하기가 힘듭니다..^^; slf4j가 코딩을 좀 더 편하게 해주기때문에 저는 성능이 비슷해도 쓸것 같습니다. ^^

    • 이동국  댓글주소 수정/삭제 2011.01.07 10:54 신고

      log4j와 slf4j 간의 로그레벨 체크를 통한 성능차는 없다고 보여집니다. 둘간의 차이는 로그 문자열의 연산비용의 차이인데요.
      log4j의 경우 로그문자열을 만들기 위한 연산비용이 항상 들어가지만, slf4j는 {} 를 사용하는 파라미터 인자 처리를 사용하면 로그레벨 체크를 먼저하고 문자열 연산을 하기 때문에 이득인 것입니다.
      기존에 slf4j를 사용하셨다면 계속 사용하시면 되겠습니다.

[블로그 백업글][2005.11.22]
JDK1.4에서 소개된 내장된 로깅기능을 사용할때, 콘솔에 뿌려지는 것을 막기 위해 다음과 같은 방법을 사용하면 된다.

(JAVA_HOME)\jre\lib\logging.properties 파일을 열어서. 아래의 부분을

Posted by 이동국
TAG jdk, 로깅

댓글을 달아 주세요