달력

12025  이전 다음

  • 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
  • 31

[SpringJDBC] PreparedStatement 파라미터 로깅하기

자바 2011. 9. 27. 15:46
SpringJDBC를 사용할때, PreparedStatement 의 파라미터를 로그에 찍기 위해서는 로그레벨을 TRACE로 해야 한다.

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

'자바' 카테고리의 다른 글

[Spring] SpringSource TC Server  (0) 2011.12.22
[eclipse] m2e 업그레이드 후 maven builder 오류  (0) 2011.10.24
[mybatis] 사용자 가이드(한국어) 등록 요청  (0) 2011.08.24
[MyBatis] MyBatis 3.0 사용자 가이드 한국어 문서 공개  (10) 2011.08.11
[SiteMesh] error-page 와 SiteMesh  (0) 2011.08.03
Posted by fromm0
|

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

자바 2010. 12. 30. 10:35
# 테스트 환경
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 의 파라미터 인자로 처리하면 성능의 이점이 있다.

'자바' 카테고리의 다른 글

[Spring] Spring AOP를 통한 선언적인 트랜잭션 관리가 제대로 작동하지 않는 경우  (1) 2011.02.01
[성능] 모델셋팅 및 리플렉션 처리..  (0) 2011.01.07
[안드로이드][프로요][미라크] 캘린더 설정  (0) 2010.11.22
[안드로이드][프로요][미라크] 계정 타입  (0) 2010.11.22
[Spring] Spring MVC에 JSR 303 Bean Validator 적용 시 발생하는 에러  (0) 2010.08.15
Posted by fromm0
|

[메모] jdk 1.4에서 로그 메시지 막기.

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

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

'자바' 카테고리의 다른 글

[framework] iBATIS의 유래….  (2) 2008.06.28
[framework] ibatis에서 동적 쿼리를 위한 remapResults  (1) 2008.06.28
[framework] Spring XML설정파일을 위한 12가지 가장 좋은 선택  (0) 2008.06.28
[개발툴] eclipse ganymede 릴리즈 임박..  (0) 2008.06.25
[개발툴] Eclipse Ganymede 릴리즈 소식  (0) 2008.06.18
Posted by fromm0
|

티스토리툴바