Log4J 로깅 비용 계산

January 03, 2016 Tech Tip

2006년 4월 30일에 이글루스 블로그에서 섰던 글입니다. 추억 팔이로 옮겨 놓습니다. 2006년 추억 속으로…. - 원문: http://okcode.egloos.com/1892085

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

Log4J를 사용하면 OutputStream에서 발생하는 자원독점 문제 해결, logging 레벨 설정을 코드와 분리, 로그 출력 방식 설정 변경 등 다양한 이점을 얻을 수 있다.

그러나 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의 운영 모드를 변경해도 동일하게 발생한다는 것을 알수 있다.(물론 일정 부분 감소할 것이다.)

1. Log4J 로깅 메소드 비용 계산

예제 코드는 다음과 같다.

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

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

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])
logger의 logging 레벨 체크
1. 현재 등록된 로거의 로깅 레벨을 체크
2. 현재 logger의 로깅 레벨이 DEBUG이면 다음 단계 진행
3. 현재 logger의 로깅 레벨이 INFO 이상이면 정지
logger의 appender에 등록된 output에 출력
1. layout 적용
2. 출력

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

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

Debug 모드일 때

로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
logger의 레벨 체크 실행
로깅 실행 - layout 적용 후 output에 로깅 적용

non-Debug 모드일 때

로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
logger의 레벨 체크 실행
실행 없이 종료

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

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

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

3. 문제 해결 코드

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

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

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

4. 문제 해결 코드의 side-effect

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

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

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

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

이러한 실행 과정은 단일 로깅일 때는 문제가 되지 않지만(로깅 전체에서 체크의 실행 비용은 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 모드 운영 중이라고 가정할 때 반복문 속에서

로그 레벨 체크
로그 레벨 체크 후 로깅
로그 레벨 체크
로그 레벨 체크 후 로깅

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

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 메소드를 사용할 경우 다음과 같은 두 가지 사항에 주의해야 할 것이다.

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

또 다른 숙제…

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

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

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

taewan.kim 블로그

Step By Step - 우공이산(愚公移山)