사실은 ThreadLocal 홍보 두번째입니다.
첫번째 글은 여기에.
(ThreadLocal은 쓰임새가 많아 수 많은 JDK 클래스 중 '내 맘대로 호감 베스트 5' 안에 들어가는 클래스입니다.)

어느날 문득...
테스트계로 사용 중인 Applcation Server에서 뿌려 대는 로그를 하염없이 보고 있다가 이런 생각이 들었습니다.

'애플리케이션에서 DEBUG 레벨로 찍는 로그 메시지가 너무 많다. 로그 레벨을 올려버리면 DEBUG 레벨의 로그를 아예 볼 수가 없다.'

그러다가 떠오른 생각,
'예외가 발생했을 때만 해당 트랜잭션에서 발생했던 로그를 모아뒀다 출력하고, 정상처리했을 때는 출력 안하면 되지 않을까?'

한번 구현해 보았습니다.

우선 테스트용 소스를 보시면 다음과 같습니다.
실제 구현 소스와 설정파일은 첨부 파일을 참조하세요.

public class LogBufferControlTest {
  Logger logger = Logger.getLogger(getClass());
 
  public void foo(int i) {
      logger.debug("하이" + i);
      bar(i);
  }

  public void bar(int i) {
      try {
          barbar(i);
      } catch (RuntimeException any) {
          logger.error("이런..." + i, any);
          throw any;
      }
  }

  public void barbar(int i) {
      if (i % 2 == 0) {
          throw new RuntimeException("Oh no!" + i);
      }
  }

  public static void main(String[] args) {
      LogBufferControlTest t = new LogBufferControlTest();
      try {
          t.foo(1);
          LogBufferControl.clear();
      } catch (Exception any) {
          LogBufferControl.flush();
      }
      try {
          t.foo(2);
          LogBufferControl.clear();
      } catch (Exception any) {
          LogBufferControl.flush();
      }
      try {
          t.foo(3);
          LogBufferControl.clear();
      } catch (Exception any) {
          LogBufferControl.flush();
      }
  }
}

main()을 보시면 foo() 메소드에 1, 2, 3을 넣어서 차례대로 호출하는데,
foo()->bar()->barbar() 의 순으로 call 됩니다.
barbar()에서는 파라미터가 2인 경우에만 예외를 발생시키도록 해 놓은 걸 보실 수 있습니다.

실제 실행시켜서 로그를 확인해 보면 파라미터가 2일 때 발생했던 로그만 출력됩니다.

이게 가능한 이유는 로그 이벤트가 발생하면 실제로 로깅하는 것이 아니라 버퍼에 넣어 둡니다.
ThreadedBuffer 클래스의 append() 메소드를 보시면,
아래와 같이 로그 메시지를 StringBuffer에 넣어둡니다.

      StringBuffer buffer = bufferPerThread.get();
      String message = layout.format(event);
      buffer.append(message);

(습관처럼 써 버린 StringBuffer보다는 thread-unsafe 한 StringBuilder가 더 효율적이겠네요.)

bufferPerThread는 아래와 같이 선언되어 있기 때문에 ,

  private static final ThreadLocal<StringBuffer> bufferPerThread =

      new ThreadLocal<StringBuffer>() {
          protected StringBuffer initialValue() {
              return new StringBuffer(INITIAL_CAPACITY);
            }
        };

StringBuffer는 스레드마다 하나씩 할당되게 되어,
해당 스레드에서만 발생한 로그 메시지를 버퍼링합니다.

실제로 버퍼링된 로그 메시지는 계속 쌓이다가,
LogBufferControl 클래스의 flush()를 호출하면 모두 출력되고,
clear() 하게 되면 출력 없이 버퍼가 비워지게 됩니다.

LogBufferControl 호출을 위의 테스트 코드에서는 명시적으로 넣어 두었습니다만,
실전에서는 Aspect화 하면 딱 좋을 것 같습니다.

아주 좋은 설계이라는 느낌은 오지 않지만 이대로도 별 문제 없지 않을까... 하는게 제 생각입니다만,
더 좋은 설계가 있다면 코멘트 주셨으면 하네요 :-)

아 그리고 이렇게 구현해 놓았더니 괜찮은 부수효과가 생기더군요.
request/response 기반의 시스템에서는 동시에 여러 스레드에서 팍팍 로그를 흩날리다(?) 보니
출력되는 appender는 정작 뒤죽박죽으로 되는 경우가 많은데,
이 경우에는 실제 출력될 때는 request 별로 모아져서 나오므로 로그가 보기 좋아집니다.


- CrossCutter -
  1. Commented by Favicon of http://younghoe.info/ BlogIcon 영회 at 2006.11.15 22:49

    호~ 아주 유용한 발상이네요.
    좋은 유스케이스가 좋은 코드를.. :)

    다만, LogBufferControl이라는 이름보다는
    다소 객체지향 간지가 나는 BufferedLogger가 어떨까요?

  2. Commented by Favicon of http://crosscutter.info BlogIcon 지훈 at 2006.11.16 09:05

    Log4j에서 Appender와 Appender를 연결할 수 있으면 디자인이나 설정도 간단해 졌을 텐데,
    소스코드까지 뒤져가며 찾아봤지만 일단 불가능... 으로 결정 내버렸습니다.
    첨부한 log4j.properties에 보면 Appender와 Appender를 연결하기 위해
    별도의 로거를 지정해버렸다는... OTL

  3. Commented by 안정효 at 2006.11.16 13:05

    참 좋내요
    저도 많은 로그중에 내가 보고 싶은 로그만 보면 좋겠다 했었거든요
    그래서 전 level지정 처럼 id level을 만들어서 설정파일에 허용가능한 id를 지정해서
    디버깅을 위한 아이디로 로그인 후 자신이 취한 action만 로그를 보도록 하면 좋겠다
    했는데 귀차니즘으로 구현은 못했구요
    멤버롤을 가지고 있는 사이트라면 가능할 것 같은데요 어떨지 모르겠내
    저만 원하는 기능인가?

SimpleDateFormat 클래스의 딜레마

엔터프라이즈 자바 2006. 11. 8. 11:27 posted by 엔트웍스
SimpleDateFormat 클래스를 사용할 때 항상 찜찜했던 부분이 이거였다.

"이 녀석을 생성하면 대체 어느 scope에 저장해야 하는가?"

이런 류의 포매팅 객체는 생성 and/or 사용에 오버헤드가 걸리는게 일반적이다.
보통은 그냥 매번 new 해서 사용하거나 DateUtil을 만들어서 static final로 박아 넣기도 했었으나... 더 나은 솔루션이 없을까 고민하던 차에 ThreadLocal을 알게 되었다.

본인이 테스트 했던 과정을 그대로 따라서 ThreadLocal이 답인지 알아보자!

먼저 간단하게 성능 테스트를 해 보았다.

1. SimpleDateFormat 백만개 생성하는데 드는데 오버헤드는?
현재 사용중인 P4 (헬쯔는 몰겠음) PC에서 얻은 결과는 다음과 같다.

SimpleDateFormat 백만개 생성 : 약 12000 ms
Object 백만개 생성 : 약 16 ms

대충 단순 Object에 비해 객체생성에 드는 비용은 750배이다.
아마 평균적인 객체에 비해 100단위의 배수가 들 것이라 추정된다.

2. SimpleDateFormat의 format()/parse()에 비교하면 어떨까?
하나의 SimpleDateFormat 을 생성하고 format()/parse() 실행 후 폐기... 를 백만번 반복한 테스트 결과는 다음과 같다.

생성 + format() 백만번 : 약 18000 ms
생성 + parse() 백만번 : 약 20000 ms

여기서 주목할 점은 parse()가 format() 보다 오래 걸린다(는 쉽게 예상된다)는 건 아니고,
생성이 대충 12000 이니까, SimpleDateFormat 생성이 format()이나 parse()에 비해 오래 걸린다는 것이다.

3. 객체 생성에 오버헤드가 걸리니까 singleton으로 바꾸면 어떨까?
젤 쉽게 구현할 수 있는 static singleton으로 바꿔봤다.
글만 쓰면 심심하니까 잠깐 코드...

public class DateUtil {
  static final DateFormat singletonDf =
      new SimpleDateFormat("yyyyMMdd");
  ...
}

이 singletonDf를 객체를 이용해서 돌려본 결과... 역시 엄청난 속도업!

format() 백만번 : 약 1500 ms

.... 그런데 좀 찜찜하다.

SimpleDateFormat의 자바독을 찾아보면 다음과 같다.

Date formats are not synchronized...

역시나 synchronization이 필요하다. 사실 synchronized 키워드 자체의 오버헤드는 별로 없다. 기억하기로는 CPU 8 instructions이 필요하다는데 그까이꺼... 다만 문제는 format()/parse() 수행 중 내내 다른 스레드는 대기해야 한다는거. SimpleDateFormat이야 워낙 초고속(위에서는 1/1000 ms 수준) 이지만 XML 파서같은 경우는 어떨까? 꽤 영향력있는 병목이 될 수도 있다.

4. 매번 생성이나 static singleton 말고는 방법이 없을까?
SimpleDateFormat을 ThreadLocal로 컨트롤 해 보자. 아래 코드와 같이...

  static final ThreadLocal<DateFormat> dfPerThread =
      new ThreadLocal<DateFormat>() {
          protected DateFormat initialValue() {
              return new SimpleDateFormat("yyyyMMdd");
          }
      };

나는 이러한 singleton을 예전부터 thread-local singleton이라고 불렀는데, 그 이전에 per-thread singleton이라 정의한 양키가 있다. 누군지는 기억이 안나지만... ㅡㅡ;

이 경우에는 매 format()/parse() 시에 dpPerThread.get().format()/parse() 형태로 후출하면 된다.
코드는 다음과 같다.

  public static String format(Date d) {
      DateFormat df = dfPerThread.get();
      return df.format(d);
  }


single thread로 돌리면 static singleton과 성능상 별 차이가 없다.
다른점이 있다면, synchronized 구간이 없다는 것이다.
이로 인해 성능상 static singleton에 비하면, 스레드가 많을 수록 그리고 synchronized 구간이 길 수록 영향이 커진다.

다만 단점이 있다면 스레드와 같은 생명주기를 가지므로, 스레드 갯수만큼 객체가 생성된다는 것이 singleton에 비하면 조금 찜찜하다.

5. 결론은 이렇다
사실은 SimpleDateFormat은 단순한 예제로 든 것일 뿐, 단순한 애플리케이션에서 반드시 ThreadLocal로 지정해서 사용해야 할 정도로 성능상 악영향을 미치지는 않을 것이다.
그러나 다음과 같은 조건을 만족한다면 ThreadLocal을 고려하면 좋을 것이다.
  • 다중 스레드 환경이다.
  • synchronized 구간이 길어서 이로 인한 영향이 크다.
  • 이를 피하기 위해 매번 객체를 생성하기에는 비용이 아깝다.
  1. Commented by Favicon of http://cbiscuit.info BlogIcon cbiscuit at 2006.11.08 13:57

    per-thread-local singleton 으로 해라..
    절충안!

  2. Commented by Favicon of http://younghoe.info/ BlogIcon 영회 at 2006.11.08 23:23

    SimpleDateFormat이 꽤나 비효율적으로 작동하나 보네요.
    몰랐네.. 흥미롭네요. :)