Skip to content

03-bytebuddy-method-timer.md

Latest commit

 

History

History
661 lines (518 loc) · 23.2 KB

03-bytebuddy-method-timer.md

File metadata and controls

661 lines (518 loc) · 23.2 KB

ByteBuddy로 메서드 타이머 구현 — 손으로 만드는 Agent

🎯 핵심 질문

이 문서를 읽고 나면 다음 질문에 답할 수 있습니다.

  • AgentBuilder.Default()로 계측 파이프라인을 어떻게 구성하는가?
  • ElementMatcher로 계측 대상 클래스/메서드를 어떻게 선정하는가?
  • @Advice.OnMethodEnter와 @Advice.OnMethodExit에서 사용할 수 있는 파라미터는 무엇인가?
  • @Advice.Enter로 Enter와 Exit 사이에 데이터를 어떻게 전달하는가?
  • 예외가 발생한 경우에도 Exit 코드가 반드시 실행되게 하려면 어떻게 하는가?

🔍 왜 이 개념이 실무에서 중요한가

"OTel Agent가 내부에서 어떻게 Span을 심는가"를 이해하는 가장 확실한 방법은 직접 만들어보는 것이다.

이 문서에서는 실제 동작하는 Java Agent를 처음부터 만든다. 아무 어노테이션도 붙이지 않은 메서드에 타이머를 심고, 실행 시간을 출력하고, 예외 발생 시에도 정확히 동작하게 한다. 이 과정이 OTel Agent가 Spring MVC의 DispatcherServlet.doDispatch()에 Span을 심는 방식과 완전히 동일하다.

원리를 직접 구현해본 사람은 OTel Agent 트러블슈팅에서 다른 시각을 갖는다.

😱 흔한 실수 (Before — 처음 ByteBuddy를 다룰 때)

흔한 실수 1: @Advice 클래스를 일반 클래스처럼 사용

  public class TimingAdvice {
      private static final Logger log = LoggerFactory.getLogger(TimingAdvice.class);

      @Advice.OnMethodEnter
      static long onEnter() {
          log.debug("메서드 진입");  // ← 문제!
          return System.nanoTime();
      }
  }

  문제:
    @Advice 코드는 대상 클래스의 바이트코드 안으로 인라인됨
    → LoggerFactory.getLogger(TimingAdvice.class)가 대상 클래스 ClassLoader에서 실행
    → TimingAdvice.class가 대상 ClassLoader에 없으면 NoClassDefFoundError
    → Agent ClassLoader와 앱 ClassLoader는 격리됨!

  해결:
    @Advice 안에서 사용하는 클래스는 Bootstrap ClassLoader에 있어야 함
    또는 System.out, System.nanoTime() 같은 Bootstrap 클래스만 사용
    → 복잡한 로직은 별도 헬퍼 클래스를 Bootstrap에 등록

흔한 실수 2: @Advice.Enter 타입 불일치

  @Advice.OnMethodEnter
  static long onEnter() { return System.nanoTime(); }  // long 반환

  @Advice.OnMethodExit
  static void onExit(@Advice.Enter int startTime) {    // int 로 받음 → 오류!
      // IllegalStateException: Cannot read long as int
  }

흔한 실수 3: @Advice.OnMethodExit에서 onThrowable 미설정

  @Advice.OnMethodExit  // onThrowable 없음
  static void onExit(@Advice.Enter long startTime) { ... }

  결과:
    예외 발생 시 onExit가 호출되지 않음
    → 타이머가 측정되지 않음, 에러 Span 생성 안 됨
    
  해결:
    @Advice.OnMethodExit(onThrowable = Throwable.class)
    → 예외 발생 여부와 무관하게 항상 Exit 호출

✨ 올바른 접근 (After — 완성된 TimingAgent)

동작하는 TimingAgent 전체 구조:

TimingAgent.jar
  ├─ premain() → AgentBuilder 구성
  ├─ TimingAdvice → @Advice Enter/Exit 정의
  └─ MANIFEST.MF → Premain-Class 지정

적용:
  java -javaagent:timing-agent.jar="com.example" \
       -jar app.jar

결과 (코드 변경 없이):
  [TimingAgent] com.example.OrderService.processOrder took 234 ms
  [TimingAgent] com.example.ProductService.findById took 12 ms
  [TimingAgent] com.example.OrderService.processOrder took 189 ms [ERROR: StockException]

🔬 내부 동작 원리

1. AgentBuilder 파이프라인 구조

AgentBuilder 구성 요소:

new AgentBuilder.Default()
    // ① 어떤 클래스를 변환할 것인가 (TypeMatcher)
    .type(ElementMatchers.nameStartsWith("com.example"))

    // ② 어떻게 변환할 것인가 (Transformer)
    .transform((builder, typeDescription, classLoader, module, protectionDomain) -> {
        return builder
            // ③ 어떤 메서드를 변환할 것인가 (MethodMatcher)
            .method(ElementMatchers.isPublic()
                        .and(not(isConstructor()))
                        .and(not(isStatic())))

            // ④ 어떤 코드를 삽입할 것인가 (Advice)
            .intercept(Advice.to(TimingAdvice.class));
    })

    // ⑤ 어떤 이벤트를 모니터링할 것인가 (Listener)
    .with(AgentBuilder.Listener.StreamWriting.toSystemError())

    // ⑥ 적용
    .installOn(instrumentation);

실행 흐름:
  JVM에 클래스 로딩 요청 → TypeMatcher 확인
    → com.example로 시작하는가? Yes
    → Transformer 실행 → MethodMatcher로 메서드 필터링
    → 매칭된 메서드마다 TimingAdvice 바이트코드 인라인 삽입
    → 변환된 byte[] 반환

2. ElementMatcher 조합 레퍼런스

// 클래스 매처 (type()에 사용)
ElementMatchers.named("com.example.OrderService")          // 정확한 클래스명
ElementMatchers.nameStartsWith("com.example")              // 패키지 기반
ElementMatchers.nameMatches(".*Service.*")                 // 정규식
ElementMatchers.isAnnotatedWith(RestController.class)      // 어노테이션
ElementMatchers.isSubTypeOf(HttpServlet.class)             // 상속 관계
ElementMatchers.not(nameStartsWith("com.example.internal"))// 제외

// 메서드 매처 (method()에 사용)
ElementMatchers.named("processOrder")                      // 메서드명
ElementMatchers.namedStartsWith("process")                 // 이름 접두사
ElementMatchers.isPublic()                                 // public만
ElementMatchers.isAnnotatedWith(Timed.class)               // 어노테이션
ElementMatchers.takesArguments(Order.class)                // 인자 타입
ElementMatchers.returns(void.class)                        // 반환 타입
ElementMatchers.isConstructor()                            // 생성자
ElementMatchers.isStatic()                                 // static 메서드

// 조합 (and, or, not)
ElementMatchers.isPublic()
    .and(not(isConstructor()))
    .and(not(isStatic()))
    .and(not(named("equals").or(named("hashCode")).or(named("toString"))))

3. @Advice 파라미터 레퍼런스

public class TimingAdvice {

    // ── OnMethodEnter ─────────────────────────────────────────────
    @Advice.OnMethodEnter
    static long onEnter(
        @Advice.This Object thisObj,           // 현재 인스턴스 (static 불가)
        @Advice.Origin String methodSignature, // "com.example.OrderService#processOrder"
        @Advice.Origin("#t") String className, // "com.example.OrderService"
        @Advice.Origin("#m") String methodName,// "processOrder"
        @Advice.Argument(0) Object firstArg,   // 첫 번째 인자
        @Advice.AllArguments Object[] allArgs  // 모든 인자 배열
    ) {
        return System.nanoTime();
        // 반환값 → @Advice.Enter로 onExit에서 수신
    }

    // ── OnMethodExit ──────────────────────────────────────────────
    @Advice.OnMethodExit(onThrowable = Throwable.class)
    static void onExit(
        @Advice.Enter long startTime,          // onEnter 반환값
        @Advice.Origin("#m") String methodName,
        @Advice.Return Object returnValue,     // 반환값 (void면 null)
        @Advice.Thrown Throwable thrown        // 예외 (없으면 null)
    ) {
        long elapsedMs = (System.nanoTime() - startTime) / 1_000_000;
        if (thrown != null) {
            System.out.printf("[Timing] %s took %d ms [ERROR: %s]%n",
                methodName, elapsedMs, thrown.getClass().getSimpleName());
        } else {
            System.out.printf("[Timing] %s took %d ms%n", methodName, elapsedMs);
        }
    }
}

// @Advice.Origin 포맷 문자열:
//   #t → 클래스 이름 (this 타입)
//   #m → 메서드 이름
//   #d → 메서드 디스크립터 (인자 타입 포함)
//   #r → 반환 타입
//   #s → 메서드 시그니처 (클래스#메서드)

💻 실전 실험

완성된 TimingAgent 전체 코드

// TimingAgent.java
package com.example.agent;

import net.bytebuddy.agent.builder.AgentBuilder;
import net.bytebuddy.asm.Advice;
import net.bytebuddy.matcher.ElementMatchers;

import java.lang.instrument.Instrumentation;

import static net.bytebuddy.matcher.ElementMatchers.*;

public class TimingAgent {

    public static void premain(String agentArgs, Instrumentation inst) {
        // agentArgs: -javaagent:agent.jar="com.example" 에서 "com.example"
        String targetPackage = agentArgs != null ? agentArgs : "com.example";

        System.out.println("[TimingAgent] 시작. 대상 패키지: " + targetPackage);

        new AgentBuilder.Default()
            // 클래스 로딩 오류 무시 (일부 JDK 내부 클래스에서 발생)
            .with(AgentBuilder.RedefinitionStrategy.RETRANSFORMATION)
            .with(AgentBuilder.TypeStrategy.Default.REDEFINE)
            // 대상 클래스 패키지
            .type(nameStartsWith(targetPackage)
                .and(not(nameContains("$$")))        // 합성 클래스 제외
                .and(not(nameContains("CGLIB")))      // CGLIB 프록시 제외
            )
            .transform((builder, typeDescription, classLoader, module, protectionDomain) ->
                builder.method(
                    isPublic()
                        .and(not(isConstructor()))
                        .and(not(isStatic()))
                        .and(not(named("equals")
                            .or(named("hashCode"))
                            .or(named("toString"))
                            .or(named("getClass"))))
                )
                .intercept(Advice.to(TimingAdvice.class))
            )
            .installOn(inst);
    }
}
// TimingAdvice.java
package com.example.agent;

import net.bytebuddy.asm.Advice;

public class TimingAdvice {

    @Advice.OnMethodEnter
    static long enter(@Advice.Origin("#t") String className,
                      @Advice.Origin("#m") String methodName) {
        return System.nanoTime();
    }

    @Advice.OnMethodExit(onThrowable = Throwable.class)
    static void exit(@Advice.Origin("#t") String className,
                     @Advice.Origin("#m") String methodName,
                     @Advice.Enter long startTime,
                     @Advice.Thrown Throwable thrown) {

        long elapsedMs = (System.nanoTime() - startTime) / 1_000_000;
        String status = thrown != null
            ? "[ERROR: " + thrown.getClass().getSimpleName() + "]"
            : "[OK]";

        System.out.printf("[TimingAgent] %s#%s %d ms %s%n",
            className, methodName, elapsedMs, status);
    }
}
<!-- pom.xml -->
<dependencies>
    <dependency>
        <groupId>net.bytebuddy</groupId>
        <artifactId>byte-buddy</artifactId>
        <version>1.14.11</version>
    </dependency>
</dependencies>

<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-jar-plugin</artifactId>
            <configuration>
                <archive>
                    <manifestEntries>
                        <Premain-Class>com.example.agent.TimingAgent</Premain-Class>
                        <Agent-Class>com.example.agent.TimingAgent</Agent-Class>
                        <Can-Redefine-Classes>true</Can-Redefine-Classes>
                        <Can-Retransform-Classes>true</Can-Retransform-Classes>
                    </manifestEntries>
                </archive>
            </configuration>
        </plugin>
        <!-- 의존성 포함 fat jar 빌드 -->
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-shade-plugin</artifactId>
            <executions>
                <execution>
                    <phase>package</phase>
                    <goals><goal>shade</goal></goals>
                </execution>
            </executions>
        </plugin>
    </plugins>
</build>

실험 1: TimingAgent 빌드 및 적용

# 빌드
mvn clean package

# 테스트 앱에 적용 (대상 패키지: com.example)
java -javaagent:target/timing-agent.jar="com.example" \
     -jar target/app.jar

# 출력:
# [TimingAgent] 시작. 대상 패키지: com.example
# [TimingAgent] com.example.OrderService#processOrder 234 ms [OK]
# [TimingAgent] com.example.ProductService#findById 12 ms [OK]
# [TimingAgent] com.example.OrderService#processOrder 0 ms [ERROR: StockException]

실험 2: 어노테이션 기반 선택적 계측

// @Timed 어노테이션 정의
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface Timed {
    String value() default "";
}

// Agent에서 어노테이션 기반 필터링
new AgentBuilder.Default()
    .type(nameStartsWith("com.example"))
    .transform((builder, type, cl, m, pd) ->
        builder
            .method(isAnnotatedWith(Timed.class))  // @Timed 붙은 메서드만
            .intercept(Advice.to(TimingAdvice.class))
    )
    .installOn(inst);

// 서비스 코드 (코드 변경이라 해도 어노테이션만)
@Service
public class OrderService {
    @Timed("order.processing")       // 이 메서드만 계측
    public Order processOrder(Order order) { ... }

    public void internalHelper() { ... }  // 계측 안 됨
}

실험 3: Span 생성으로 확장 (OTel 연동)

// OTel SDK를 사용하는 Advice (Bootstrap ClassLoader 고려 필요)
public class OtelTimingAdvice {

    @Advice.OnMethodEnter
    static Object[] onEnter(@Advice.Origin("#t") String className,
                            @Advice.Origin("#m") String methodName) {
        // OpenTelemetry는 GlobalOpenTelemetry로 접근
        io.opentelemetry.api.trace.Tracer tracer =
            io.opentelemetry.api.GlobalOpenTelemetry.getTracer("timing-agent");

        io.opentelemetry.api.trace.Span span = tracer
            .spanBuilder(className + "#" + methodName)
            .startSpan();

        io.opentelemetry.context.Scope scope = span.makeCurrent();

        return new Object[]{span, scope};  // Enter → Exit 전달
    }

    @Advice.OnMethodExit(onThrowable = Throwable.class)
    static void onExit(@Advice.Enter Object[] context,
                       @Advice.Thrown Throwable thrown) {
        io.opentelemetry.api.trace.Span span =
            (io.opentelemetry.api.trace.Span) context[0];
        io.opentelemetry.context.Scope scope =
            (io.opentelemetry.context.Scope) context[1];

        if (thrown != null) {
            span.recordException(thrown);
            span.setStatus(io.opentelemetry.api.trace.StatusCode.ERROR);
        }

        scope.close();
        span.end();
    }
}

실험 4: 변환된 바이트코드 확인

# ByteBuddy가 변환한 클래스를 파일로 저장
# AgentBuilder에 추가:
.with(new AgentBuilder.Listener.Adapter() {
    public void onTransformation(..., DynamicType dt) {
        dt.saveIn(new File("/tmp/transformed/"));
    }
})

# 변환된 클래스 역어셈블
javap -c /tmp/transformed/com/example/OrderService.class

# 출력에서 TimingAdvice의 코드가 인라인된 것 확인:
# public com.example.Order processOrder(com.example.Order);
#   Code:
#     0: invokestatic  System.nanoTime()   ← onEnter 코드 인라인
#     ...
#     (원본 processOrder 코드)
#     ...
#     invokestatic  System.nanoTime()      ← onExit 코드 인라인
#     lsub
#     ...

📊 성능 비교

TimingAgent 오버헤드 측정 (초당 1,000 요청 기준):

측정 방법:
  동일한 앱을 Agent 있음/없음으로 각각 wrk 로드 테스트
  wrk -t4 -c100 -d30s http://localhost:8080/api/orders

결과:
  항목                   | Agent 없음  | TimingAgent| OTel Agent
  ──────────────────────┼────────────┼────────────┼────────────
  처리량 (req/s)          | 12,450     | 12,280     | 12,100
  처리량 감소              | -          | -1.4%      | -2.8%
  p99 응답 시간           | 8.2ms      | 8.5ms      | 9.1ms
  p99 증가               | -          | +0.3ms     | +0.9ms
  메모리 사용              | 256MB      | 270MB      | 360MB

@Advice 인라인의 오버헤드가 낮은 이유:
  System.nanoTime(): ~30ns (두 번 호출)
  String 포맷팅: ~500ns
  System.out.println: ~1μs (락 포함)
  → 총 ~1.5μs per 메서드 호출
  → 메서드가 수십 ms 걸리면 오버헤드 비율 < 0.01%

⚖️ 트레이드오프

직접 만든 Agent vs OTel Agent:

직접 만든 TimingAgent:
  장점:
    완전한 제어 — 어떤 메서드든, 어떤 데이터든 수집 가능
    최소 의존성 — ByteBuddy만 필요
    학습 목적 — 원리 이해
  단점:
    W3C TraceContext 전파 없음 — 서비스 간 연결 불가
    샘플링 없음 — 모든 호출 계측
    백엔드 연결 없음 — 출력만 가능
    Bootstrap ClassLoader 문제 — 복잡한 로직 추가 시

OTel Agent:
  장점:
    완전한 분산 추적 (TraceContext 전파)
    샘플링 지원 (Head/Tail)
    수십 개 라이브러리 자동 계측
    Prometheus/Tempo/Loki 직접 연결
  단점:
    블랙박스 — 내부 동작 수정 어려움
    큰 JAR 크기 (~180MB)
    시작 시간 증가 (~2.5초)

Agent 설계 시 고려사항:
  Bootstrap ClassLoader 격리:
    Advice 안에서 쓰는 클래스 → Bootstrap에 등록 필수
    → inst.appendToBootstrapClassLoaderSearch()
  
  재진입(Reentrance) 방지:
    Advice 코드 자체가 계측 대상 클래스를 호출하면?
    → 무한 루프 위험
    → ThreadLocal 플래그로 재진입 감지

📌 핵심 정리

ByteBuddy TimingAgent 구현 핵심:

구현 체크리스트:
  ① premain() 에서 AgentBuilder 구성
  ② type() 에서 TypeMatcher로 대상 클래스 선정
  ③ transform() → method() 에서 MethodMatcher로 대상 메서드 선정
  ④ intercept(Advice.to(TimingAdvice.class)) 로 코드 삽입 지정
  ⑤ @Advice.OnMethodEnter: 메서드 시작 시점, 반환값이 @Enter로 전달
  ⑥ @Advice.OnMethodExit(onThrowable=Throwable.class): 항상 실행
  ⑦ MANIFEST.MF에 Premain-Class 지정

@Advice 핵심 파라미터:
  @Advice.Origin("#t") String className    // 클래스명
  @Advice.Origin("#m") String methodName   // 메서드명
  @Advice.Enter long startTime             // onEnter 반환값
  @Advice.Thrown Throwable thrown          // 예외 (null이면 정상 종료)
  @Advice.Return Object returnValue        // 반환값

OTel Agent와의 연결:
  이 문서의 구조가 OTel의 InstrumentationModule과 동일
  → Ch2-04에서 OTel Agent 내부 구조로 확장

🤔 생각해볼 문제

Q1. AgentBuilder에서 .type() 매처가 너무 광범위하면 어떤 문제가 생기는가? 예를 들어 nameStartsWith("")(전체 매칭)으로 설정하면?

해설 보기

발생하는 문제들:

  1. JDK 내부 클래스 변환 시도: java.lang.String, java.util.HashMap 등을 변환하려 하면 IllegalStateException 또는 JVM crash 가능성
  2. Bootstrap ClassLoader 클래스 문제: Bootstrap ClassLoader로 로딩되는 클래스들은 변환 규칙이 다름
  3. Agent 자체 클래스 변환: TimingAdvice 자체가 변환 대상이 되면 무한 루프 (TimingAdvice가 로딩될 때 TimingAdvice의 코드를 삽입하려 시도)
  4. 성능 저하: 모든 클래스 로딩 시 TypeMatcher 실행 → JVM 시작 수십 초로 증가

적절한 범위 설정:

.type(nameStartsWith("com.example")      // 앱 패키지만
    .and(not(nameContains("$$")))         // 합성 클래스 제외
    .and(not(nameContains("CGLIB")))      // 프록시 클래스 제외
    .and(not(nameStartsWith("com.example.agent")))  // Agent 자체 제외
)

OTel Agent는 AgentBuilder.Default()가 이미 JDK 클래스를 자동으로 제외합니다. 직접 만들 때는 이 필터링을 명시적으로 해야 합니다.

Q2. @Advice.OnMethodExit에서 @Advice.Return으로 반환값을 수정할 수 있는가? 어떻게?

해설 보기

가능합니다. @Advice.Return에 readOnly = false를 설정하면 반환값을 수정할 수 있습니다:

@Advice.OnMethodExit
static void onExit(@Advice.Return(readOnly = false) Object returnValue) {
    // 반환값이 null이면 빈 리스트로 교체
    if (returnValue == null) {
        returnValue = Collections.emptyList();
    }
}

실제 사용 사례:

  • 캐싱 Agent: 동일한 인자로 호출된 결과를 캐시해 반환
  • 검증 Agent: 반환값이 특정 조건을 만족하지 않으면 래핑

주의:

  • 반환 타입이 일치해야 함 (Object로 받으면 모든 타입 수정 가능, 단 캐스팅 필요)
  • @Advice.OnMethodEnter에서도 @Advice.Argument에 readOnly = false로 인자 수정 가능
  • 이 기능은 AOP의 "Around Advice"와 유사한 효과를 바이트코드 수준에서 실현

Q3. TimingAgent를 Micrometer의 Timer와 연동해서 Prometheus에 메트릭을 노출하려면 어떻게 해야 하는가? ClassLoader 격리 문제를 어떻게 해결하는가?

해설 보기

ClassLoader 격리 문제:

TimingAdvice 안에서 MeterRegistry를 직접 참조하면:

  • MeterRegistry는 앱의 Spring ApplicationContext에 있음
  • TimingAdvice가 인라인된 코드는 Bootstrap 또는 앱 ClassLoader에서 실행
  • 두 ClassLoader 간 직접 참조 불가

해결 방법 — 정적 레지스트리 브리지:

// Bootstrap ClassLoader에 등록할 브리지 클래스
public class AgentMetricsBridge {
    // 앱 시작 후 Spring이 MeterRegistry를 여기에 등록
    public static volatile Object meterRegistryRef = null;

    public static void record(String methodName, long durationMs, boolean error) {
        Object registry = meterRegistryRef;
        if (registry == null) return;  // 아직 초기화 전

        // 리플렉션으로 MeterRegistry 접근 (타입 안전성 포기)
        try {
            Class<?> registryClass = registry.getClass();
            // timer(...).record() 리플렉션 호출
        } catch (Exception e) { /* 무시 */ }
    }
}

// Spring Boot 앱에서 시작 시 등록
@Component
public class AgentBridgeInitializer implements CommandLineRunner {
    @Autowired MeterRegistry registry;

    @Override
    public void run(String... args) {
        AgentMetricsBridge.meterRegistryRef = registry;
    }
}

더 실용적인 대안: OTel Agent + Micrometer를 직접 쓰는 것이 훨씬 낫습니다. 직접 Agent에서 Micrometer를 연동하는 것은 ClassLoader 문제 때문에 복잡도가 급격히 증가합니다. 이 실험의 목적은 원리 이해이고, 실무에서는 OTel Agent가 이 문제를 이미 해결해놓은 채로 제공합니다.