로깅 추적을 위한 AOP 적용과 이후 성능 차이 그리고 why ?!

개요

사내에서 만든 서비스에 메서드 전후로 AOP를 걸고 쓰레드별로 추적하는 기능을 덧붙여서 사용해볼 기회가 있었다. 성능이 어떻게 달라질 것인지 궁금했다. 이 글은 AOP 적용 이전과 이후 성능 차이를 기록하고 이를 분석해본 글이다. 그리고 이 결과에 대한 피드백으로 들어온 어떤 질문에 대해 고민해 본 내용을 소개한다.

사용한 툴

장비: macbook pro 13` 2020 (m1), 16GB, Ventura 13.5
성능 측정: JMeter, Spring Actuator(Prometheus, Grafana)
개발: Mvc: Springboot 2.6.7, mysql 8.0

테스트의 특성상 많은 더미 데이터를 사용하지는 않았다.

1. Log Trace AOP 적용 이전

단건 조회

request: /api/v2/process-data/templates/Generic-Template-XXXX
db 현황: 더미 데이터 10건

유저 1명을 위한 테스트 (테스트 1)

첫 번째로, 유저가 1명일 때의 성능을 살펴보았다.

throughput: 36.4/sec
응답 시간: 24~30ms
TPS: 36~40/sec

유저가 100명일 때 (테스트 2)

두 번째로, 유저가 100명일 때의 결과를 살펴보면 다음과 같다.

throughput: 213.3/sec
응답시간: 450~500ms로 유저가 1명일 때보다 높게 나왔다.
TPS: 200~220/sec

유저가 500명일 때 (테스트 3)

마지막으로, 유저가 500명일 때의 테스트이다.

throughput은 208.4/sec로, 유저가 100명일 때와 비슷한 수준이다.
응답 시간과 TPS도 유저가 100명일 때와 크게 차이나지 않았다.
throughput : 208.4/sec
response: 450~500/ms
tps: 200~220/sec

단건 조회 종합 결과

Throughput: 유저가 늘어나도 throughput은 비교적 안정적으로 유지되었다. 100명에서 500명으로 늘어났을 때 throughput은 크게 차이나지 않았다. 일정 수준 이상의 부하에는 잘 대응한다.
Response Time: 유저가 증가하면서 응답 시간도 증가했다. 특히 유저가 1명일 때와 100명, 500명일 때의 차이가 많이 났다. 이는 고부하 상황에서는 성능이 저하될 가능성이 있음을 암시한다.
TPS: 초당 트랜잭션 수(TPS)도 유저가 증가하면서 줄어들었지만, 100명과 500명일 때는 큰 차이가 없었다. 이는 서버가 일정량의 부하에는 꽤 잘 대응하고 있지만, 부하가 일정 수준을 넘어서면 성능 저하가 발생한다고 볼 수 있다.

검색 조회

request: api/version/resource/subresource/action?searchParameter=value&searchCriteria=criteriaType
db 현황: 더미 데이터 10건

유저 1명을 위한 테스트 (테스트 1)

throughput : 30.7/sec
응답시간: avg 30/ms (peak 285)
TPS: 28~32/sec

유저가 100명일 때 (테스트 2)

throughput: 153.6/sec
응답시간: 600~800ms
TPS: 100~180/sec

유저가 500명일 때 (테스트 3)

throughput: 157.7/sec
응답시간: 2800~3200ms
TPS: 140~160/sec

검색 조회 종합 결과

Throughput

검색 조회에서는 유저가 1명일 때 throughput이 30.7/sec, 100명일 때는 153.6/sec, 500명일 때는 157.7/sec으로 측정되었다. 즉, 유저가 많아질수록 throughput이 늘어나지만 100명과 500명 사이에서는 그 차이가 크지 않았다.

Response Time

응답 시간은 유저가 1명일 때는 평균 30ms, 100명일 때는 600 ~ 800ms, 500명 일때는 2800ms ~ 3200ms로 측정되었다. 유저가 증가할수록 응답 시간이 급격히 증가하며, 특히 500명일 때는 크게 증가한 것을 볼 수 있다.

TPS

TPS도 유저 수가 증가하면서 감소하는 경향을 보였다. 100명과 500명일 때의 차이는 비교적 작았으나, 유저가 1명일 때와는 큰 차이를 보였다.

2. Log Trace AOP 적용 이후

적용 예시

단건 조회

request: /api/v2/data-processing/templates/{template-id}
db 현황: 더미 데이터 10건

유저가 100명일 때 (테스트 1)

throughput: 202.4/sec
응답시간: 470~600ms
TPS: 160~220/sec

검색 조회

request: service/api/v2/fees/templates/search?searchKeyword=TEMPLATE_CODE&searchType=templateId
db 현황: 더미 데이터 10건

유저가 100명일 때 (테스트 1)

throughput: 159.2/sec
응답시간: 600~700ms
TPS: 140~160/sec

3. 종합 결론

1. 성능에 대한 결론

단건 조회와 검색 조회 모두에서 볼 수 있듯이, 유저의 수가 증가하면서 응답 시간은 상승하는 경향을 보였다. 특히, 유저가 500명일 때 응답 시간이 급격히 증가했다. 하지만, throughput과 TPS는 유저가 증가해도 비교적 안정적으로 나온다.

2. AOP 적용에 대한 결론

AOP 적용 이후는 유저가 100명인 상황에 대한 테스트만 진행하였다. 100명 기준, 적용 전과 후를 비교해보면 다음과 같다.

적용 전 단건 조회 & 검색 조회

throughput: 213.3/sec, 153.6/sec
응답시간: 450~800ms
TPS: 200~220/sec, 100~180/sec

적용후 단건 조회 & 검색 조회

throughput: 202.4/sec, 159.2/sec
응답시간: 470~700ms
TPS: 160~220/sec, 140~160/sec

AOP 적용 전과 이후의 응답시간은 크게 차이나지 않으며, throughput과 TPS 모두 유의미한 변화를 보이지 않고 있어 성능상의 영향은 크게 없는 것으로 결론내렸다.

4. 질문

로그 AOP 적용 후에도 성능 차이가 나지 않은 이유에 대해서 생각해 보셨나요?

5. 왜 그럴까?

`LogTrace` AOP가 성능에 큰 영향을 미치지 않는 이유

먼저 스프링에서 AOP가 작동하는 방식에 대해서 생각해보아야 한다.

AOP

1. JDK 다이나믹 프록시

Relection을 사용
해당 AOP 클래스가 하나 이상의 인터페이스 구현할 시 적용됨

Java Api인 Reflection 사용시 성능에 부정적인 영향을 미친다. 공식 문서에 따르면 refrelction 작동시 Jvm의 Optimization을 사용하지 않아 퍼포먼스 저하를 가져온다.

https://docs.oracle.com/javase/tutorial/reflect/

2. CGLIB

Code Generator Library라는 이름과 같이 바이트 코드를 조작하여 클래스를 생성 (단, 런타임)
대상 클래스가 인터페이스를 구현하지 않으면 작동
스프링 3.2, 부트 1.4 버전부터 스프링 코어 패키지에 포함

이와 같은 이유로 다음과 같이 작성된 LogTrace 의 작동시 성능에 큰 영향을 미치지 않게 된다.

@Slf4j
@Aspect
@Component
@RequiredArgsConstructor
public class GenericLogAspect {

    private final GenericLogger genericLogger;

    @Around("execution(* com.example.project..*.*(..))")
    public Object logExecution(ProceedingJoinPoint joinPoint) throws Throwable {
        LogStatus logStatus = null;
        Object result = null;

        try {
            String methodDescription = joinPoint.getSignature().toShortString();
            logStatus = genericLogger.startLogging(methodDescription);

            result = joinPoint.proceed();
            genericLogger.endLogging(result, logStatus);
            return result;
        } catch (Exception e) {
            genericLogger.logException(result, logStatus, e);
            throw e;
        }
    }

    // 다른 포인트컷 정의는 필요에 따라 추가
}

Log

두 번째로 생각해볼 점은 로깅이다. 수많은 로깅이 찍힌다면 해당 연산에 대한 부하를 감당하는 과정에서 성능 저하가 발생할 수 있음을 충분히 유추해볼 수 있다.

Slf4j의 작동 방식

SLF4J (Simple Logging Facade for Java)는 Java용 로깅 퍼사드 또는 추상화 레이어이다. 즉, 자체적으로 로깅을 수행하지 않으며, 다양한 로깅 프레임워크(Log4j, Logback, JUL 등)에 대한 일종의 인터페이스를 제공한다.

다양한 구현체들이 런타임 시점에 바인딩 될 수 있는데, default 값은 Logback이다. Logback은 이전의 사용되던 Log4j보다 향상된 성능과 다양한 필터링 옵션을 제공한다. 그러나 기본 작동 방식은 동기방식으로 해당 구현체는 로깅 과부하 연산이 걸릴 수 있다.

비동기 설정

찾아 보니 프로젝트의 logback 설정에 다음과 같은 비동기 설정이 있었다.

    <appender name="ASYNC-STDOUT" class="ch.qos.logback.classic.AsyncAppender">
        <param name="BufferSize" value="8196"/>
        <param name="locationInfo" value="true"/>
        <param name="neverBlock" value="true"/>
        <param name="includeCallerData" value="false"/>
        <param name="discardingThreshold" value="0"/>
        <appender-ref ref="STDOUT"/>
    </appender>

    <appender name="ASYNC-INFO" class="ch.qos.logback.classic.AsyncAppender">
        // 생략 
        <appender-ref ref="INFO"/>
    </appender>

    <appender name="ASYNC-ERROR" class="ch.qos.logback.classic.AsyncAppender">
        // 생략 
        <appender-ref ref="ERROR"/>
    </appender>

AsyncAppender는 별도의 스레드를 사용하여 비동기로 로깅을 수행할 수 있게 한다.

그래서 애플리케이션의 메인 스레드에 부담을 주지 않을 수 있게 된다.

결론

AOP를 구현하여도 왜 성능 저하가 미비한가? 이에 대한 의문에 대해 AOP 특성과 로깅 설정을 탐구하여 이와 같이 추론해볼 수 있었다.

아직 남는 의문점들은 다음과 같고 추후 과제로 살펴두고 생각해볼 예정이다.

로그를 비동기로 처리할 경우, 로그의 순서나 타이밍에 대한 정확성이 떨어질 수 있지 않을까?

예를 들어, 여러 스레드가 동시에 로그를 출력하는 경우, 비동기 로깅을 사용하면 로그 메시지가 기록된 순서와 실제 발생한 순서가 다를 수 있다. 설정에서는 DEBUGGING의 경우 비동기 설정을 하지 않음으로써 이와 같은 취약점을 해소한 것으로 파악했다. 그럼에도, 다른 로깅들이 정확한 로깅을 하지 못할 수 있을 가능성이 있다면 정확성 신뢰의 문제가 발생할 것 같다.

더 정확한 분석을 위해서는 다른 메트릭 지표가 필요하다

보다 정밀한 분석을 하려면 Advice 실행 시간, 메모리 사용량 등 다양한 지표를 바탕으로 검증해볼 필요가 있다.

저작자표시 비영리 변경금지

'질문 연습' 카테고리의 다른 글

컴퓨터는 실제로 배열의 데이터에 index로 접근할까? (1)	2023.11.24
왜 int, String 배열은 스트림(Stream)으로 쉽게 변환되는데 char 배열은 안 되는 것일까?! (자바 캐릭터 배열 스트림으로 변환하기) (0)	2023.06.24

로깅 추적을 위한 AOP 적용과 이후 성능 차이 그리고 why ?!

개요

사용한 툴

목차

1. Log Trace AOP 적용 이전

단건 조회

유저 1명을 위한 테스트 (테스트 1)

유저가 100명일 때 (테스트 2)

유저가 500명일 때 (테스트 3)

단건 조회 종합 결과

검색 조회

유저 1명을 위한 테스트 (테스트 1)

유저가 100명일 때 (테스트 2)

유저가 500명일 때 (테스트 3)

검색 조회 종합 결과

Throughput

Response Time

TPS

2. Log Trace AOP 적용 이후

적용 예시

단건 조회

유저가 100명일 때 (테스트 1)

검색 조회

유저가 100명일 때 (테스트 1)

3. 종합 결론

1. 성능에 대한 결론

2. AOP 적용에 대한 결론

4. 질문

5. 왜 그럴까?

LogTrace AOP가 성능에 큰 영향을 미치지 않는 이유

AOP

1. JDK 다이나믹 프록시

2. CGLIB

Log

Slf4j의 작동 방식

비동기 설정

결론

로그를 비동기로 처리할 경우, 로그의 순서나 타이밍에 대한 정확성이 떨어질 수 있지 않을까?

더 정확한 분석을 위해서는 다른 메트릭 지표가 필요하다

'질문 연습' 카테고리의 다른 글

관련글

티스토리툴바

`LogTrace` AOP가 성능에 큰 영향을 미치지 않는 이유