Google AdSense (text)

hidden logo stop

Moving

거지 같은 이글루스 광고노출 정책이 싫어서,
새 보금자리(http://blog.leocat.kr/)로 이사감.

[Groovy] 멋진 Logger Injection과 logging하기 Computer & Program

Groovy는 logging하기 좋게 되어 있다. 단, 1.8 버전 이후부터 ㅋㅋ

Logging을 하기 위해 해주어야할 것은 클래스(type)에 annotation 하나 달아주는 것 뿐이다. Annotation은 사용하고 싶은 logger에 따라 여러가지가 있다.

일단 slf4j를 사용한 예제를 보자.
아래 내용을 Slf4jLoggerClass.groovy가 아닌 다른 이름으로 저장하자. (모두 알겠지만, 마지막줄에 스크립트로 실행했으니 스크립트가 파일명과 같은 이름으로 클래스가 생성된다. 때문에 스크립트 클래스명과 Slf4jLoggerClass 이름이 중복될 수 있으니까..)

@Grab('org.slf4j:slf4j-simple:1.7.2')
//@Grab(group='org.slf4j', module='slf4j-simple', version='1.7.2') // 같은 내용

import groovy.util.logging.Slf4j

@Slf4j
class Slf4jLoggerClass {
  public Slf4jLoggerClass() {
    println "\nSLF4J Logging (${log.name}: ${log.class}):"
    log.info "${this.printAndReturnValue(1)}"
    log.debug "${this.printAndReturnValue(2)}"
  }

  public String printAndReturnValue(int newValue) {
    println "SLF4J: Print method invoked for ${newValue}"
    return "SLF4J: ${newValue}"
  }
}

new Slf4jLoggerClass()


우선 @Grab 으로 사용할 logger 라이브러리의 dependency를 먼저 걸어주고.. 사용할 logger annotation(여기서는 @Slf4j)을 클래스에 달아주면 log라는 변수가 클래스에 logger가 inject된다. 때문에 annotation만 달아주면 쉽게 logging을 할 수 있어서 정말 편하다. 여기서는 org.slf4j:slf4j-api 대신 org.slf4j:slf4j-simple을 사용했는데, slf4j에서 사용할 간단한 logger가 구현되어 있어서 slf-sample을 사용해도 좋다.

$groovy test.groovy

SLF4J Logging (Slf4jLoggerClass: class org.slf4j.impl.SimpleLogger):
SLF4J: Print method invoked for 1
[main] INFO Slf4jLoggerClass - SLF4J: 1

클래스 객체를 생성하면 생성자에서 info와 debug 레벨로 로깅을 시작한다. Default logging 레벨이 info 레벨이기 때문에 info 레벨은 로깅이 되지만, debug 레벨은 로깅이 되지 않는다. 그리고 여기서 주의깊게 봐야할 것은 info 레벨의 로깅 메시지 자체가 생성되지 않는다는 것이다. info 레벨을 logging할 때는 logging할 레벨이기 때문에 printAndReturnValue() 메소드가 실생되어 "SLF4J: Print method invoked for 1" 메시지가 찍힌다. 하지만 debug 레벨은 메소드조차 실행되지 않는다. 왜냐하면 @Slf4j doc에 아래와 같은 내용이 쓰여 있다.

log.name(exp)

is mapped to
if(log.isNameLoggable()) {
  log.name(exp)
}
Groovy 만쉐이~!!

이 내용을 다시 설명하면..
Logging을 남길 때 exp로 내용을 쓰게 되는데, 보통 이 exp는 현재 변수값 등을 찍기 위해 문자열 조합 등을 많이 사용하게 된다. Java는 문자열은 불변 클래스이기 때문에 문자열 조합에는 많은 메모리가 사용될 수 있다. 특히 String 객체를 "+" 연산으로 마구 합쳐대다가는.. 어익후..
때문에 logging 메소드를 실행하기 전에 현재 logging 레벨을 체크하는 코드를 사용한다. 아래의 Java 코드를 보자. Logging 레벨이 info 레벨 이상이라면 사용하지 않는 logging 메시지를 조합할 필요 없이 건너 뛸 수 있게 if문으로 체크를 하게 된다. 하지만 groovy는 이런 내용을 알아서 해주기 때문에 logging 메소드를 그냥 사용해도 불필요한 내용을 수행하지 않게 됐다.
오옷!! Groovy 겁나 멋져~~!! +ㅅ+

// logging하지 않는 레벨이라도 문자열 조합을 하게 된다.
logger.debug("Method called with args: [" + arg1 + ", " + args2 + "]");

// logging하는 레벨이 아니면 if문을 건너뛰어 문자열 조합을 하지 않는다.
if(logger.isDebugEnabled()) logger.debug("Method called with args: [" + arg1 + ", " + args2 + "]");


+ 수정 덧
권남님의 댓글로 Slf4j에도 logging 레벨을 체크하는 기능과 문자열 연산 등의 기능이 있다는걸 알았다. 아마도 비교적 최근 버전인 groovy 1.8에서 이런 annotation이 추가된걸로 보아, Slf4j나 다른 라이브러리들의 내용을 좀 참조하지 않았을까 싶다. 그리고 groovy가 아닌 java와 같은 상황에서는 이런 형태의 로깅이 불필요한 문자열 연산 등을 줄이고 보다 효율적인 로깅을 할 수 있을 것 같다.

LOGGER.debug("Hello {}", name);

SLF4J의 장점
Thoughts on Java logging and SLF4J


- 참고
Groovy - Logging
Easy Groovy Logger Injection and Log Guarding

핑백

덧글

  • 권남 2012/10/18 10:02 # 답글

    요즘 Sigel님의 groovy 관련 포스팅 잘보고 있습니다.

    근데 위의 Slf4j 예제는 잘못된 것입니다.

    Slf4j의 자동 조건체크를 통한 로깅은 Groovy의 것이 아니라 원래 Java Slf4j 라이브러리의 것이고, 성능을 높이려면 다른 방식으로 사용해야 합니다.

    logger.debug("Method called with args: {} {}, arg1, arg2);

    http://devday.tistory.com/entry/SLF4J%EC%9D%98-%EC%9E%A5%EC%A0%90 참조하시길.
  • Sigel 2012/10/19 00:15 #

    우아~ Slf4j에 저런 기능이 있군요. Java에서 사용할 때도 유용하겠네요. 좋은 정보 감사합니다.

    그런데 @Slf4j groovy doc을 보면 (본문에도 썼지만) 아래와 같은 내용이 있습니다. Groovy API doc에 있는걸로 봐서는 groovy 자체도 이 기능을 지원하는듯 싶네요. 아마 groovy가 그 기능을 가져왔을 수도 있을 것 같아요. @Log, @Commons, @Log4j, @Slf4j 모두 이런 설명이 있습니다.

    log.name(exp)

    is mapped to
    if(log.isNameLoggable()) {
    log.name(exp)
    }
  • 권남 2012/10/18 10:12 # 답글

    Groovy의 경우 GString을 사용해서 로깅할 경우 slf4j 처럼 조건에 부합할 때만 동적으로 문자열 구성을 해주는지는 확인이 필요해보이네요.
    또한, log.debug('xx')를 했을 때 저기서 if 조건이 들어간 메소드를 호출하는 것인지 log.debug()문 전체가 구문 분석시 if 조건문으로 대체되는 것인지도 확인은 필요해보입니다. 완전 구문 대체라면 성능에 Slf4j 스타일로 로그 메시지를 넘기지 않더라도 성능상의 영향은 없습니다.
  • Sigel 2012/10/19 00:15 #

    Groovy의 closure를 응용해서 예제를 이렇게 살짝 바꿔봤습니다.

    log.info "${println 'in closure(1)'; this.printAndReturnValue(1)}"
    log.debug "${println 'in closure(2)'; this.printAndReturnValue(2)}"

    println으로 찍히는 것이 'in closure(1)'만 있고, 2는 없는걸 보니, debug에 있는 GString 객체는 생성되지 않은 것 같습니다. GString은 lazy loading을 하기 때문에 toString()으로 문자열이 사용되기 전까지는 closure부분이 실행되지 않으니까요..
  • 권남 2012/10/18 10:15 # 답글

    Changelog 확인해봤는데, 로깅 검사 메소드에 대한 프록시가 아닌 완전 구문 대체 맞군요. 마음대로 써도 성능상의 영향이 없는 것 맞습니다.

    Another particularity of these logger AST transformations is that they take care of wrapping and safe-guarding logger calls with the usual isSomeLevelEnabled() calls. So when you write log.info 'Car constructed', the generated code is actually equivalent to:
    if (log.isLoggable(Level.INFO)) {
    log.info 'Car constructed'
    }

댓글 입력 영역

Google AdSense (text/image)