Sun Developer Network 공식 블로그

프로그램이 실패한 이유를 분석하고자 할 때 실패 시 프로그램이 실제로 무엇을 하는 중이었는지는 매우 중요한 정보가 됩니다. 대부분의 경우에는 스택 트레이스로 확인할 수 있지만 정보를 사용할 수 없거나 실패 시 처리 중이던 데이터에 관한 정보가 필요한 경우도 있습니다.

이전에는 이것이 log4j 또는 자바 로깅 API와 같은 로깅 프레임워크를 사용한 후 모든 필요한 로그 문을 수동으로 쓰고 유지 관리하는 것을 의미했습니다. 이 방법은 매우 지루하고 오류가 많으며 오히려 자동화에 적합한 작업입니다. 자바 5는 Java Instrumentation 메커니즘을 추가했습니다. 이 메커니즘은 로드 시 클래스의 바이트 코드를 검사 및 수정할 수 있는 "자바 에이전트"를 제공할 수 있는 메커니즘입니다.

이 기사는 표준 자바 로깅 API를 통해 모든 클래스의 모든 메소드에 대한 시작 및 종료 로깅을 투명하게 추가하는 자바 에이전트의 구현 방법을 보여줍니다. Hello World를 예로 사용했습니다.

public class HelloWorld {
    public static void main(String args[]) {
        System.out.println("Hello World");
    }
}

여기에서는 동일한 프로그램에 시작 및 종료 문을 추가했습니다.

import java.util.Arrays;
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingHelloWorld {
    final static Logger _log = Logger.getLogger(LoggingHelloWorld.class.getName());

    public static void main(String args[]) {
        if (_log.isLoggable(Level.INFO)) {
            _log.info("> main(args=" + Arrays.asList(args) + ")");
        }
        System.out.println("Hello World");
        if (_log.isLoggable(Level.INFO)) {
            _log.info("< main()");
        }
    }
}

기본 로거 형식은 다음과 유사한 출력을 생성합니다.

2007-12-22 22:08:52 LoggingHelloWorld main
INFO: > main(args=[])
Hello World
2007-12-22 22:08:52 LoggingHelloWorld main
INFO: < main()

각 로그 문은 두 줄로 인쇄됩니다. 첫 번째 줄에는 타임스탬프, 지정한 로그 이름, 호출을 한 메소드가 기록되며 두 번째 줄에는 지정한 로그 텍스트가 기록됩니다.

기사의 나머지 부분은 로드 시 바이트 코드를 조작하여 어떻게 원본 Hello World 프로그램이 로깅 Hello World처럼 작동하는지 보여줍니다. 조작 메커니즘은 자바 5에 추가된 Java Instrumentation API입니다.

Java Instrumentation API 사용

지정된 main 메소드를 실행하기 전에 자바가 youragent.jar 매니페스트에 나열된 premain(...) 메소드를 호출하도록 JVM 인수 -javaagent:youragent.jar 또는 -javaagent:youragent.jar=argument를 사용하여 자바를 호출할 수 있습니다. 이 premain(...) 메소드를 사용하여 transform(...) 메소드를 제공하는 transformer 클래스 파일을 시스템 클래스 로더에 등록할 수 있습니다. 이 메소드는 그 때부터 모든 각 클래스 로딩의 일부로 호출되며 클래스 로더가 실제 Class로 처리하기 전까지 실제 바이트 코드를 조작할 수 있습니다

이를 위해서는 몇 가지 부분을 포함시켜야 합니다.

ClassFileTransformer를 구현하는 클래스

로드 시 각 클래스가 transform(...) 메소드를 호출합니다. 인수는 전체 클래스에 대한 완전한 원본 바이트 코드입니다.

static void premain() 메소드를 제공하는 클래스

premain(...) 메소드는 위의 변환기를 클래스 로더에 등록해야 합니다. 또한 명령줄에서 제공한 인수도 처리할 수 있습니다.

올바른 MANIFEST.MF 파일

MANIFEST.MF는 premain() 메소드를 포함하는 클래스를 참조하는 Pre-Class: .. 행을 포함해야 합니다. 또한 외부 .jar 파일을 참조하기 위해 Boot-Class-Path:를 사용합니다.

이 매니페스트를 포함한 .jar 파일에 코드를 넣어야 합니다. 그렇지 않을 경우, 이유를 알리지 않고 실패합니다.


com.runjva.instrumentation.LoggerAgent 샘플 에이전트

이 섹션에서는 com.runjva.instrumentation.LoggerAgent라는 샘플 에이전트를 보여줍니다. 이 샘플 에이전트는 java.lang.instrument.ClassFileTransformer 인터페이스를 구현하고 필요한 premain(...) 메소드를 제공합니다.

transform(...) 메소드의 실제 바이트 코드 조작은 자바 스닢펫 컴파일러와 상위 수준 바이트 코드 조작 루틴을 제공하는 JBoss "Javassist" 라이브러리를 사용하여 수행됩니다. 컴파일러는 컴파일된 후 적절한 위치에 삽입되는 자바 문자열 스닢펫을 작성하여 조작할 수 있도록 합니다.

서명 추출 및 반환 값 유형 추출 메소드는 복잡한 편이며 목록에는 없지만 샘플 코드 .zip 파일에 있는 com.runjva.instrumentation.JavassistHelper에 위치합니다.

샘플 코드와 Javassist 및 배경 기사 링크는 참고 자료 섹션을 참조하십시오.

다음은 com.runjva.instrumentation.LoggerAgent 클래스입니다.

package com.runjva.instrumentation;

import java.lang.instrument.*;
import java.util.*;
import javassist.*;

public class LoggerAgent implements ClassFileTransformer {

  public static void premain(String agentArgument,
      Instrumentation instrumentation) {
    if (agentArgument != null) {
      String[] args = agentArgument.split(",");
      Set argSet = new HashSet(Arrays.asList(args));

      if (argSet.contains("time")) {
        System.out.println("Start at " + new Date());
        Runtime.getRuntime().addShutdownHook(new Thread() {
          public void run() {
            System.out.println("Stop at " + new Date());
          }
        });
      }
      // ... 여기에서 추가 에이전트 옵션 처리
    }
    instrumentation.addTransformer(new LoggerAgent());
  }

premain(...) 메소드는 클래스 변환기로 LoggerAgent를 추가할 책임이 있습니다. 또한 문자열 인수를 쉼표로 구분된 옵션 목록으로 간주하며 time 옵션이 주어진 경우, 날짜는 현재 및 종료 시간에 출력됩니다.

  String def = "private static java.util.logging.Logger _log;";
  String ifLog = "if (_log.isLoggable(java.util.logging.Level.INFO))";

  String[] ignore = new String[] { "sun/", "java/", "javax/" };

  public byte[] transform(ClassLoader loader, String className,
      Class clazz, java.security.ProtectionDomain domain,
      byte[] bytes) {

    for (int i = 0; i < ignore.length; i++) {
      if (className.startsWith(ignore[i])) {
        return bytes;
      }
    }
    return doClass(className, clazz, bytes);
  }

실제 개체로 인스턴스화하기 전에 시스템 클래스 로더는 로드한 모든 클래스에 대해 transform(...) 메소드를 호출합니다. 각 클래스에는 필요한 해당 클래스를 로드하기 위한 코드가 포함되어 있어 런타임 라이브러리 클래스에 로거를 추가하지 않으므로 클래스 이름을 살펴보고 수정되지 않은 라이브러리 클래스를 반환해야 합니다(마침표가 아니라 슬래시로 구분됨).

  private byte[] doClass(String name, Class clazz, byte[] b) {
    ClassPool pool = ClassPool.getDefault();
    CtClass cl = null;
    try {
      cl = pool.makeClass(new java.io.ByteArrayInputStream(b));
      if (cl.isInterface() == false) {

        CtField field = CtField.make(def, cl);
        String getLogger = "java.util.logging.Logger.getLogger("
            + name.replace('/', '.') + ".class.getName());";
        cl.addField(field, getLogger);

        CtBehavior[] methods = cl.getDeclaredBehaviors();
        for (int i = 0; i < methods.length; i++) {
          if (methods[i].isEmpty() == false) {
            doMethod(methods[i]);
          }
        }
        b = cl.toBytecode();
      }
    } catch(Exception e) {
      System.err.println("Could not instrument  " + name
          + ",  exception : " + e.getMessage());
    } finally {
      if (cl != null) {
        cl.detach();
      }
    }
    return b;
  }

doClass(...) 메소드는 제공된 바이트 스트림 분석을 위해 Javassist를 사용합니다. 실제 클래스(인터페이스가 아닌)인 경우, _log라는 로거 필드가 추가되어 클래스 이름으로 초기화됩니다. 비어있지 않은 각 메소드는 그때 doMethod(...)로 처리됩니다. finally 절은 메모리 사용량을 줄이기 위해 Javassist 풀에서 클래스 정의를 다시 삭제하도록 합니다.

  private void doMethod(CtBehavior method)
      throws NotFoundException, CannotCompileException {

    String signature = JavassistHelper.getSignature(method);
    String returnValue = JavassistHelper.returnValue(method);

    method.insertBefore(ifLog + "_log.info(\">> " + signature
        + ");");

    method.insertAfter(ifLog + "_log.info(\"<< " + signature
        + returnValue + ");");
  }
}

doMethod(...) 클래스는 각 메소드의 시작과 끝에 삽입하기 위해 if (_log.isLoggable(INFO))_log.info(...) 스닢펫을 작성합니다. 로깅 시스템의 구성 없이 출력을 생성할 수 있는 가장 낮은 수준이기 때문에 이 수준을 선택한 것입니다.

JavassistHelper 클래스는 샘플 코드 .zip 파일에 있습니다.(참고 자료 참조)

샘플 MANIFEST.MF 파일

여기에서는 premain 메소드를 포함하는 클래스를 가리키는 행과 에이전트에서 사용 가능한 Javassist를 만드는 행만 필요합니다.

Premain-Class: com.runjva.instrumentation.LoggerAgent
Boot-Class-Path: ../lib/javassist.jar

dist/loggeragent.jar은 lib/javassist.jar이 필요하므로 ../lib는 상대 경로입니다.

샘플 build.xml 파일

build.xml 파일에는 컴파일 대상, .jar 대상, 전통적인 HelloWorld 대상, 로거 에이전트가 활성인 HelloWorld 대상이 포함됩니다.

<project name="Logger Agent (Java 5+)" default="all">
  <target name="all" depends="compile,jar,withoutAgent,withAgent"/>

  <target name="withAgent" description="run with logging added by java agent">
    <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld">
      <jvmarg value="-javaagent:dist/loggeragent.jar=time"/>
    </java>
  </target>

  <target name="withoutAgent" description="run normally">
    <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld">
    </java>
  </target>

  <target name="compile" description="compile classes">
    <delete dir="bin" />
    <mkdir dir="bin" />
    <javac source="1.4" srcdir="src" destdir="bin" debug="true" 
              optimize="true" verbose="false" classpath="lib/javassist.jar">
    </javac>
  </target>

  <target name="jar" depends="compile" description="create agent jar">
    <jar basedir="bin" destfile="dist/loggeragent.jar" manifest="Manifest.mf"/>
  </target>
</project>

ant를 실행하면 다음과 유사한 결과가 나옵니다.

Buildfile: build.xml

compile:
   [delete] Deleting directory /home/ravn/workspace/com.runjva.instrumentation/bin
    [mkdir] Created dir: /home/ravn/workspace/com.runjva.instrumentation/bin
    [javac] Compiling 3 source files to /home/ravn/workspace/com.runjva.instrumentation/bin

jar:
      [jar] Building jar: /home/ravn/workspace/com.runjva.instrumentation/dist/loggeragent.jar

withoutAgent:
     [java] Hello World

withAgent:
     [java] Start at Fri Apr 18 21:13:53 CEST 2008
     [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main
     [java] INFO: >> main(args=[])
     [java] Hello World
     [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main
     [java] INFO: << main(args=[])
     [java] Stop at Fri Apr 18 21:13:54 CEST 2008

all:

BUILD SUCCESSFUL
Total time: 2 seconds

출력은 로그 문이 추가되어 실제로 출력을 생성했음을 보여줍니다. 로그 문의 실제 순서는 로그 문이 System.err에 쓰여지며 HelloWorld의 출력과 시간 정보가 System.out에 쓰여지므로 실행 시마다 달라질 수 있습니다.

결론

Java Instrumentation API는 소스 코드나 컴파일된 바이트 코드를 변경하지 않고 런타임 시 자바 코드에 메소드 호출 로그를 투명하게 추가하기 위해 사용될 수 있습니다. 로그 문이 자동으로 생성되게 하면 로그의 정보를 항상 최신으로 유지할 수 있으며 프로그래머는 로그의 생성을 수동으로 하는 지루한 작업에서 해방될 수 있습니다.

참고 자료

• 이 기사의 샘플 코드
• java.lang.instrument용 공식 자바 6 Javadocs
• 자습서, 다운로드 및 포럼을 포함하는 Javassist 홈 페이지
• "Instrumentation: 자바 5 클래스 파일 변환을 사용한 애플리케이션 수정," R.J. Lorimer가 Javalobby에 기고한 기사로서 기본 사항을 간략히 설명
• "자바 5에서 Log4J 가속화" Inigo Surguy가 작성하였으며 클래스 로드 시 활성화되지 않은 로그 문을 삭제하도록 instrumentation을 사용하는 방법을 설명. 이 에이전트와 유사하지만 코드에 로그 문이 있어야 함.

Thorbjorn Ravn Andersen은 IBM iSeries에서 자바로 레거시 Cobol 애플리케이션을 위한 도우미 프로그램, 웹 서비스, 프론트엔드를 만드는 수석 소프트웨어 엔지니어입니다.


이 글의 영문 원본은
Add Logging at Class Load Time with Java Instrumentation
에서 보실 수 있습니다.