Log4J 로깅 비용 계산

1. 2006년 4월 30일에 제가 쓴 포스팅 입니다. 이글루스에 있던건데 의미가 있는것 같아서 옮겨 놓습니다. 원문은 이글루스 블러그입니다.

---

Log4J 로깅 비용 계산

기존의 System.out.println() 으로 로깅 할 때 발생하는 문제의 대안으로 Log4J를 요즘 많이 사용한다.

Log4J를 사용하면 OutputStream시 발생하는 자원독점 문제 해결, logging 레벨 설정을 코드와 분리, 로깅 output target 설정 변경 등 다양한 잇점을 얻을 수 있다. 그러나 Log4J가 실행될 때 발행하는 비용을 계산해 보면 Log4J를 사용할 때 주의가 필요하다.

무작정 사용하는 것은 WAS 전체에 심각한 문제를 발생 시킬 수 있다. 모 사이트에서 JVM의 GC가 자주 발생하는 문제가 발생하여 시스템 전체에 심각한 문제가 발생한 사례가 있었다. 물론 Log4J가 문제의 핵심은 아니었지만 어느 정도 영향은 미쳤다고 생각된다.

지금 다룰 내용은 "Log4J The Complete Manual" 23 페이지에 나온 내용을 참조하였다.
이 내용을 메뉴얼을 읽을 때는 심각하게 받아 들이지 않았지만 실제 사례를 접하니 간과할 수만은 없는 문제인 듯 싶다.

문제 코드 분석

문제가 발생한 사이트는 Struts를 기반으로 하는 프레임웍 구조를 갖고 있었다. Session 정보를 추출하기 위하여 다음과 같은 코드가 공통 코드 레벨에서 수행되고 있었다.

while( i.hasNext()  ){
  Map.Entry e = (Map.Entry) i.next();
  logger.debug("TABLE KEY : " + e.getKey() );
  logger.debug( "SESSION ID : " + ((HttpSession) e.getValue()).getId() );
}      

특정 상황에서 이 코드는 246번의 반복을 수행하였고, 두 개의 debug()이 실행하면서 각각 8메가의 임시 객체를 생성하였다. 해당 while문이 수행되면서 16메가의 임시 객체를 생성하였다.

물론 문제의 while문이 구동할 때 Log4J는 DEBUG 모드로 운영중인 상태였다.

이 코드로 발생하는 문제는 Log4J를 DEBUG 모드로 운영 중이기 때문에 발생한 것이고 WARNING이나 ERROR 모드로 운영하면 문제가 발생하지 않는다고 생각할 수도 있다. 그러나 Log4J가 실행되는 비용을 계산해 보면 이러한 문제는 Log4J의 운영 모드를 변경해도 동일하게 발생한다는 것을 알수 있다.(물론 일정 부분 감소는 할 것이다.)

Log4J 로깅 메소드 비용 계산

logger.debug("Entry number: "+i+" is "+String.valueOf(entry[i]));

예제 코드와 같은 코드가 있다고 할 때 다음과 같은 순서로 실행된다.

1. logging 문자열 생성
1. String 문자열 1개 생성: "Entry number: "
2. String 문자열 1개 생성 총 2개: "Entry number: " + i
3. String 문자열 1개 신규 생성, + 결합 1개 생성, 총 4개: 신규 생성: " is ", 결합 문자열: "Entry number: " + +i+" is "
4. String 문자열 1개 신규 생성, + 결합 1개 생성, 총 6개: 신규생성: String.valueOf(entry[i]), 결합문자열: "Entry number: "+i+" is "+String.valueOf(entry[i])
2. logger의 logging 레벨 체크
1. 현재 등록된 로거의 로깅 레벨을 체크
2. 현재 logger의 로깅 레벨이 DEBUG이면 다음단계 진행
3. 현재 logger의 로깅 레벨이 INFO 이상이면 정지
3. logger의 appender에 등록된 output에 출력
1. layout 적용
2. 출력

위와 같은 순서로 실행된다.

Log4j 운영 모드에 따른 비용 계산

• Debug 모드일 때
1. 1번 로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
2. 2번 logger의 레벨 체크 실행
3. 3번 로깅 실행 - layout 적용 후 output에 로깅 적용
• non-Debug 모드일 때
1. 1번 로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
2. 2번 logger의 레벨 체크 실행
3. 3번 실행 없이 종료

로그의 모드에 따라서 Log4J에서 생략되는 부분은 3번에 국한된다. 즉 로깅 문자열 생성이나 로그 레벨 체크의 비용은 발생한다. 여기서 로그레벨 체크는 전체 로깅 비용의 1%이하이고 극히 적은 비용을 발생하기 때문에 2번은 큰 문제가 되지 않을 수 있다. 그러나 1번의 발생 비용은 경우에 따라서 매우 심각해 질 수도 있다.

1번의 로깅 문자열은 스트링을 "+"하는 방식이기 때문에 수백번의 loop안에서 발생하거나 로깅 로직이 빈번하게 발생하는 조건에서는 temporary object를 양산하는 로직이 될 가능성이 크다.

위의 Log4j 운영 모드에 따른 실행 순서에서 알수 있듯이 이것은 로깅 모드를 변경한다고 해서 발생하지 않는 부분은 아니다.

문제 해결 코드

if(logger.isDebugEnabled(){
  logger.debug("Entry number: "+i+" 
    is "+String.valueOf(entry[i]));
}

위와 같은 코드의 사용이 바람직 하다. 이러한 코드는 Log4J의 예제에서 나오는 isDebugEnabled() 메소드를 이용하는 방법이다. 실제 프로젝트에서 보변 isDebugEnabled 메소드의 사용을 간과 하는 경우가 많다.

이 코드를 사용하면 로깅 문자열을 생성하기 전에 로깅 레벨을 체크하는 isDebugEnabled 메소드를 실행하여 로깅을 실행할 것인가를 미리 체크하게 된다. 기본적인 코드이지만 이러한 코드를 사용하는 것은 매우 중요하다.

문제 해결 코드의 side-effect

이 코드는 DEBUG 모드일대 부가적인 문제를 발생 시킨다.

if(logger.isDebugEnabled() { 
  logger.debug("Entry number: "+i+" is "+String.valueOf(entry[i]));  
}

이 코드는 DEBUG 모드일 때 LOGGER의 실행 레벨 체크를 두번한다는 단점을 갖는다.

isDubugEnabled 메소드에서 한번 체크하고 debug 메소드에서 다시 체크한다. debug 모드에서 로깅 레벨 체크후 degub 상태이면 로깅을 한다.

이러한 실행 과정은 단일 로깅일 때는 문제가 되지 않지만(로깅 전체에서 체크의 실행 비용은 1% 이하이다.) debug 메소드가 loop 문 안에 있거나, 하나의 메소드에서 debug 메소드가 여러번 호출될 때는 문제가 될수 있다. 1%이하라도 반복적으로 실행된다면 문제가 될 것이다.

public void foo(Object[] a) {
  for(int i = 0; i < a.length; i++) {
    if(logger.isDebugEnabled()){
       logger.debug("Original value of entry number: "+i+" is "+a[i]);
    }
    
    a[i] = someTransformation(a[i]);

    if(logger.isDebugEnabled()){
       logger.debug("After transformation the value is "+a[i]); 
    }
  }
} 

위 와 같은 메소드가 있을 경우에는 반복문속에서 두번의 debug 메소드가 실행된다. debug 모드 운영 중이라고 가정할 때 반복문 속에서

1. 로그레벨 체크
2. 로그레벨 체크 후 로깅
3. 로그레벨 체크
4. 로그레벨 체크 후 로깅

의 순서로 실행된다. 반복문 자체도 문제지만 반복적인 로깅 체크 역시 문제이다. 이러한 코드는 다음과 같이 변경하는 것이 바람직하다.

public void foo(Object[] a) {
  boolean isLogging = logger.isDebugEnabled();
  for(int i = 0; i < a.length; i++) {
    if(isLogging ){
      logger.debug("Original value of entry number: "+i+" is "+a[i]);
    }

    a[i] = someTransformation(a[i]);

    if(isLogging ){
       logger.debug("After transformation the value is "+a[i]);
    }
  }
} 

작은 결론 debug 메소드 사용시 주의 사항

지금까지 debug 메소드에 대해서 알아 보았다. debug 메소드를 사용할 경우 다음과 같은 두가지 사항에 주의해야한다.

1. isDebugEnabled 메소드를 사용하여 사전에 로그레벨 체크: 불필요한 로깅 문자열 생성 비용 절감
2. 반복문에서는 isDebugEnabled 메소드를 반복문 외부에서 실행하여 결과 저장 및 반복문 안에서 재사용: 불필요한 로깅 레벨 중복 체크의 비용 절감

Log4J를 사용함으로써 예전에 로깅 문제의 만은 부분은 해결되고 있지만 Log4J에 대한 올바른 사용에 주의를 기울일 필요가 있다. 지금은 debug 메소드만을 다루었지만 debug 외의 info(), warning(), error(), fatal() 메소드 역시 동일한 문제를 내포하고 있다.

이러한 고민에 앞서 로깅 관련 코드를 작성할 때 로깅 문자열 생성에 대한 각별한 주의가 필요한 것 같다.

무심코 작성한 코드 한줄이 폭탄이 될수도 있다.....^