메서드 단위 속도측정

목적 : 리팩토링을 위한 기준을 세웁니다.

기능 설명

• 메서드 측정 클래스

import lombok.*;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

import java.time.LocalDateTime;
import java.util.ArrayList;
import java.util.List;

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

    public static final List<EData> eDataList = new ArrayList<>();
    public static final ThreadLocal<EData> eData = ThreadLocal.withInitial(MethodExecutionTimeAspect.EData::new);

    @Around("execution(* com.x.apps.*.service.*.*(..)), @annotation(org.springframework.transaction.annotation.Transactional)")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        String path = joinPoint.getSignature().toString();
        String serviceName = joinPoint.getSignature().getDeclaringTypeName();
        String methodName = joinPoint.getSignature().getName();
        long startTime = System.nanoTime();
        Object proceed = joinPoint.proceed();
        long endTime = System.nanoTime();
        long duration = (endTime - startTime);
        double seconds = (double) duration / 1_000_000_000.0;
        if (seconds > 10.0 && !isExceptionMethod(methodName)) {
            log.error(path + " executed in " + seconds + " seconds.\\n check this method.");
        } else {
            log.info(path + " executed in " + seconds + " seconds");
        }
        eData.get().setPath(path);
        eData.get().setServiceName(serviceName);
        eData.get().setMethodName(methodName);
        eData.get().setExecutedSeconds(seconds);
        eData.get().setExecutedAt(LocalDateTime.now());
        return proceed;
    }

    private boolean isExceptionMethod(String methodName) {
        return "callBridge".equals(methodName) || "callLimitInquiryAPI".equals(methodName);
    }

    @Getter
    @Setter
    public static class EData {
        private String path;
        private String serviceName;
        private String methodName;
        private Double executedSeconds;
        private Double transactedSeconds;
        private Integer queryCount;
        private LocalDateTime executedAt;
    }
}

• 트랜잭션 측정 클래스

import java.util.List;
import lombok.extern.slf4j.Slf4j;
import org.hibernate.EmptyInterceptor;
import org.hibernate.Transaction;

@Slf4j
public class QueryInterceptor extends EmptyInterceptor {

    private static final List<String> QUERY_INFORMATION_LOG_PROFILES = List.of("local", "local_stage");
    public final ThreadLocal<QueryInfo> queryInfo = ThreadLocal.withInitial(QueryInfo::create);
    private final ThreadLocal<Integer> queryCount = ThreadLocal.withInitial(() -> 0);
    private final ThreadLocal<Long> startTime = ThreadLocal.withInitial(() -> 0L);

    @Override
    public String onPrepareStatement(String sql) {
        queryCount.set(queryCount.get()+1);
        queryInfo.get().write(sql);
        return super.onPrepareStatement(sql);
    }

    @Override
    public void beforeTransactionCompletion(Transaction tx) {
        startTime.set(System.nanoTime());
    }

    @Override
    public void afterTransactionCompletion(Transaction tx) {
        long endTime = System.nanoTime();
        long duration = (endTime - startTime.get());
        double seconds = (double) duration / 1_000_000_000.0;
        int cnt = queryCount.get();
        String queryInformation = queryInfo.get().read();
        log.info("Transaction times : " + seconds + " seconds");
        log.info("Queries executed in this transaction : " + queryCount.get());
        if (QUERY_INFORMATION_LOG_PROFILES.contains(profile)) {
            log.info(queryInformation);
        }
        if ((profile.contains("prod") || profile.equals("stg")) && eData.get().getPath() != null && eData.get().getExecutedSeconds() > 10) {
            eData.get().setQueryCount(cnt);
            eData.get().setTransactedSeconds(seconds);
            eDataList.add(eData.get());
        }
        queryCount.remove();
        startTime.remove();
        queryInfo.remove();
        eData.remove();
        super.afterTransactionCompletion(tx);
    }

	}

• 엔티티

import lombok.*;
import org.springframework.data.jpa.domain.support.AuditingEntityListener;

import javax.persistence.*;
import java.io.Serializable;
import java.time.LocalDateTime;

@Entity
@Builder
@NoArgsConstructor
@AllArgsConstructor
public class EData extends BaseDomainWithId {
    private String path;
    private String serviceName;
    private String methodName;
    private Double executedSeconds;
    private Double transactedSeconds;
    private Integer queryCount;
    private LocalDateTime executedAt;
    private String profile;
}

• 스케쥴러

import lombok.RequiredArgsConstructor;
import org.springframework.context.annotation.Conditional;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Component
@Conditional(EDataProfile.class)
@RequiredArgsConstructor
@Component
public class EDataScheduler {

    private final EDataService service;

    @Scheduled(cron = "0 0 * * * *")//매 1시간 마다
    public void saveEData() {
        service.save();
    }

}

궁금증

1. 서버에서 가장 오래 걸리는 메서드는 어떤 메서드일까?
2. 트랜잭션 시간이 메서드 시간보다 더 긴 경우가 어떻게 있을 수 있을까?

집계

• 링크 : https://docs.google.com/spreadsheets/d/1b9iqR81kHWM5msV05S4c3uZLzNh3Qg4les_L0prNmQ8/edit#gid=507167219
• 기간 : 2023-05-18 13:00 ~ 2023-06-23 11:30
• 저장기준
  1. 측정시간 10초 이상
  2. 트랜잭션을 사용하는 메서드

결론

• 서드 파티 호출 메서드는 실행시간이 길고 쿼리 카운트가 적다.
• → 응답을 받는부분은 불가항력적인 부분이므로 집계에 제외한다.
• 메서드 실행시간 대비 쿼리수가 지나치게 많다.
• → 트랜잭션이 없는 메서드의 경우 집계에 오류가 있어 수정. 집계에서 제외.
• 메서드 실행시간 대비 쿼리수가 상대적으로 적다.
• → 쿼리에 많은 리소스를 쓰고있으므로 쿼리튜닝을 한다.
• 한 메서드에서 쿼리가 10개 이상 실행되는 경우에는 N+1이 발생되지않는지 소스를 점검한다.→ 리팩토링 기준
• → (쿼리실행개수 / 메서드 실행시간) > 전체 평균