[Snail Catch] 슬로우 쿼리 로그 수집

🎯 아키텍처

---

 

✅ 초기 아케텍처

 

SDK 에서 제공하는 기능은 크게 3가지 입니다. 

 

1. SQL 쿼리 감지 

 

JPA, QueryDSL 에서 Hibernate 를 통해 전송되는 SQL 쿼리를 감지 후 수집합니다. 

 

2. 슬로우 쿼리 판별 후 로그 생성 

 

수집된 쿼리에 대해 느린 쿼리인지를 판별합니다. 이후 SQL, 메서드명, 실행 시간 등을 추출해 하나의 로그 형식으로 생성합니다. 원래는 실행계획도 함께 추출하려 했으나 바인딩 파라미터(?) 를 포함한 쿼리가 추출됩니다. 이는 실제 런타임시 대입되기 때문에 정확한 값에 대한 추출이 힘들어 일단은 보류하려 합니다.

 

3. 생성된 로그 모니터링 서버로 전송

 

생성된 로그를 모니터링 서버로 전송해야 합니다. 이때, 로그 전송의 네트워크 부하를 줄이고 성능을 향상시키기 위해 Bulk 처리와 비동기 전송 방식을 사용하여 로그를 효율적으로 전송하려 합니다.

 

 

🎯P6Spy 를 활용한 쿼리 낚아채기 + 콘솔로그 남기기

---

P6Spy 란 ?

 

P6Spy는 JDBC 드라이버를 감싸서 SQL 쿼리를 로그로 출력해주는 오픈소스 라이브러리입니다. 주로 Spring Boot, Hibernate, MyBatis 같은 Java 기반 애플리케이션에서 실행되는 실제 SQL 쿼리를 확인하기 위해 사용됩니다. 기존의 Hibernate 에서는 쿼리를 보여줄때 '?' 가 포함된 바인딩 되기 전의 쿼리를 보여줍니다. 보안을 위해 이와 같은 선택을 했지만 실제로 콘솔에서 바인딩된 값을 봐야할때도 있었습니다. P6Spy 는 이러한 불편함을 해소하고자 바인딩된 실제 SQL 을 제공합니다.

 

실행계획을 추출하기 위해서는 이런 바인딩된 쿼리가 반드시 필요합니다. 그래서 이번 프로젝트에서는 P6Spy 를 함께 사용해 실제 DB 에 쏘는 쿼리를 수집하고, 실행계획을 추출해 사용자들에게 쿼리 튜닝에 필요한 정보를 간편하게 보여주려 합니다.

 

 

이번 포스팅에서 구현하는 과정은 다음과 같습니다.

(1) JPA, QueryDSL 등에서 DB 로 쏘는 SQL 을 P6Spy 를 통해 감지한다.

(2) 감지한 쿼리를 각각의 쓰레드에서 관리한다.

(3) 쿼리에 대한 정보 (SQL, 실행 시간, 실행 계획) 등의 정보를 로그로 콘솔 출력을 한다.

 

 

✅  사용자로부터 포인트컷을 전달받는다.

 

사용자마다 JPA, QueryDSL 등을 관리하는 패키지 구조가 다릅니다. 때문에 포인트컷을 하드 코딩 하는것이 아닌, 사용자가 application.yml 과 같은 설정파일을 통해 직접 등록하는 방식으로 포인트컷을 지정합니다.

 

package com.snailcatch.snailcatch.config;

import org.springframework.boot.context.properties.ConfigurationProperties;

@ConfigurationProperties(prefix = "slowquery")
public class SlowQueryProperties {

    private String repositoryPointcut;

    public String getRepositoryPointcut() {
        return repositoryPointcut;
    }

}

 

@ConfigurationProperties(prefix = "slowquery") 을 통해 사용자가 설정한 포인트 컷을 주입받습니다. 즉, 아래와 같이 SDK 를 사용하는 사용자가 설정하면 포인트컷 등록이 완료됩니다.

 

slowquery:
  repository-pointcut: execution(* com.snailcatch.repository..*(..))

 

 

 

✅  P6Spy 설정

package com.snailcatch.snailcatch.config;

import org.springframework.boot.autoconfigure.condition.ConditionalOnClass;
import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingBean;
import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
import org.springframework.boot.autoconfigure.jdbc.DataSourceProperties;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

import javax.sql.DataSource;

import com.p6spy.engine.spy.P6SpyDriver;
import org.springframework.boot.jdbc.DataSourceBuilder;

@Configuration
@ConditionalOnClass(P6SpyDriver.class)
@ConditionalOnProperty(prefix = "snailcatch.p6spy", name = "enabled", havingValue = "true", matchIfMissing = true)
public class P6SpyAutoConfiguration {

    @Bean
    @ConditionalOnMissingBean
    public DataSource dataSource(DataSourceProperties properties) {
        return DataSourceBuilder.create()
                .driverClassName("com.p6spy.engine.spy.P6SpyDriver")
                .url(properties.getUrl().replace("jdbc:mysql", "jdbc:p6spy:mysql"))
                .username(properties.getUsername())
                .password(properties.getPassword())
                .build();
    }
}

 

기존 MySQL 을 사용할때 URL 을 jdbc:mysql://...  처럼 사용합니다. 하지만 P6Spy 를 통해 쿼리를 감지하기 위해서 jdbc:p6spy:mysql://... 와 같은 형태의 URL 을 지정해야 합니다. 물론 사용자가 직접 변경해도 가능하지만, SDK 를 사용하는 입장에서 관련된 설정을 최소화 하는게 사용자게 더 나은 경험을 제공할 수 있다 생각했습니다.

 

즉, 위 설정 클래스를 통해 P6Spy 에 대한 설정에 대해 전적으로 책임을 SDK 에게 위임하는 것 입니다. 

 

 

✅   감지된 쿼리를 관리하는 저장소

public interface SlowQueryCollector {
    void addQuery(String query);
    List<String> getQueries();
    void clear();
}

public class ThreadLocalSlowQueryCollector implements SlowQueryCollector {
    private static final ThreadLocal<List<String>> queryHolder = ThreadLocal.withInitial(ArrayList::new);

    @Override
    public void addQuery(String query) {
        queryHolder.get().add(query);
    }

    @Override
    public List<String> getQueries() {
        return queryHolder.get();
    }

    @Override
    public void clear() {
        queryHolder.remove();
    }
}

 

감지된 쿼리를 관리하는 구현체 입니다. ThreadLocal 은 자바에서 스레드마다 독립적인 값을 저장할 수 있도록 도와주는 클래스 입니다. 동일한 ThreadLocal 인스턴스를 여러 스레드에서 사용하더라고, 각 스레드는 자신의 고유한 값을 가지기 때문에 여러 요청이 들어왔을때 쿼리가 엉키는 경우를 방지할 수 있습니다. 

 

단, ThradLocal 을 사용할때 조심해야할 점은 반드시 쓰레드에서 사용후 remove() 를 호출해 값을 비워줘야 합니다. 만약, 이전에 사용된 스레드를 다음 스레드에서 사용한다면 이전에 사용된 ThreadLocal 이 내부에 저장되기 때문에 문제가 발생하빈다. 이러한 이유 때문에 반드시 ThreadLocal 사용 후 값을 비워줘야 합니다.

 

✅  쿼리 인터셉터

public class SlowQueryInterceptor implements MethodInterceptor {

    private static final Logger log = LoggerFactory.getLogger(SlowQueryInterceptor.class);

    private final SlowQueryCollector queryCollector;
    private final ExecutionPlanLogger executionPlanLogger;
    private final DataSource dataSource;

    public SlowQueryInterceptor(SlowQueryCollector queryCollector,
                                ExecutionPlanLogger executionPlanLogger,
                                DataSource dataSource) {
        this.queryCollector = queryCollector;
        this.executionPlanLogger = executionPlanLogger;
        this.dataSource = dataSource;
    }

    @Override
    public Object invoke(MethodInvocation invocation) throws Throwable {
        queryCollector.clear();

        long startTime = System.currentTimeMillis();
        Object result = invocation.proceed();
        long duration = System.currentTimeMillis() - startTime;

        List<String> collectedQueries = new ArrayList<>(queryCollector.getQueries());
        logQueryDetails(invocation, duration, collectedQueries);

        queryCollector.clear();
        return result;
    }

    private void logQueryDetails(MethodInvocation invocation, long duration, List<String> queries) {
        String formattedSqls = formatSqls(queries);
        String executionPlans = generateExecutionPlans(queries);
        String methodName = getMethodSignature(invocation);

        log.info(LogFormatter.formatLog(methodName, duration, formattedSqls, executionPlans));
    }

    private String formatSqls(List<String> queries) {
        return queries.stream()
                .map(SqlFormatter::formatSql)
                .collect(Collectors.joining("\n"));
    }

    private String generateExecutionPlans(List<String> queries) {
        return queries.stream()
                .filter(this::isSelectQuery)
                .map(query -> executionPlanLogger.explainQuery(dataSource, query))
                .collect(Collectors.joining("\n"));
    }

    private boolean isSelectQuery(String query) {
        return query.trim().toLowerCase().startsWith("select");
    }

    private String getMethodSignature(MethodInvocation invocation) {
        return invocation.getMethod().getDeclaringClass().getSimpleName()
                + "." + invocation.getMethod().getName();
    }
}

 

SlowQueryInterceptor 클래스는 메서드가 실행할때 쿼리 실행 시간, SQL 내용, 네이밍 등의 정보를 남깁니다.

 

이때, MethodInterceptor 를 상속받아 구현하고자 하는 기능을 끼워넣는 일종의 프록시 역할을 할 수 있게끔 도와줍니다. 직접 만든 로직은 invoke() 를 오버라이드 받아 자세한 기능을 구현합니다.

 

 

 

✅  포인트컷에 쿼리 인터셉터가 동작할 수 있게 도와주는 설정 파일

@Configuration
public class SlowQueryAspect {

    private final SlowQueryProperties properties;
    private final DataSource dataSource;
    private final ExecutionPlanLogger executionPlanLogger;
    private final SlowQueryCollector queryCollector;


    public SlowQueryAspect(SlowQueryProperties properties, DataSource dataSource, SlowQueryCollector queryCollector, ExecutionPlanLogger executionPlanLogger) {
        this.properties = properties;
        this.dataSource = dataSource;
        this.executionPlanLogger = executionPlanLogger;
        this.queryCollector = queryCollector;
    }

    @Bean
    public Advisor slowQueryAdvisor() {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression(properties.getRepositoryPointcut());
        MethodInterceptor interceptor = new SlowQueryInterceptor(queryCollector, executionPlanLogger, dataSource);
        return new DefaultPointcutAdvisor(pointcut, interceptor);
    }
}

 

SlowQueryProperties 에서 설정한 포인트컷에 SlowQueryInterceptor 를 적용하는 역할을 합니다.즉, AOP Advisor 로 등록해 지정한 메서드의 호출을 감싸고 쿼리 수집 후 로그로 남기도록 설정한 클래스입니다.

 

 

✅ Bean 등록을 위한 설정

com.snailcatch.snailcatch.aop.aspect.SlowQueryAspect
com.snailcatch.snailcatch.config.SlowQueryAutoConfiguration
com.snailcatch.snailcatch.config.P6SpyAutoConfiguration

 

SDK 를 제공하는 입장에서, @SpringBootApplication 과 같은 애노테이션을 사용하지 않으므로 직접 수동으로 BEan 을 등록해야 합니다. 그렇지 않으면 SDK 를 설치하더라도, SlowQueryAspect, SlowQueryAutoConfiguration, P6SpyAutoConfiguration 와 같은 설정 클래스들을 인식하지 못합니다.

 

(이외에 로그 포맷 형식과 같은 유틸성 클래스에 대해 궁금하시면 포스팅 아래 깃허브에서 전체 코드를 확인해주세요!)

 

 

 

자! 이제 다른 프로젝트에서 SDK 를 설치해 사용해봅시다.

 

 

✅ 사용자 build.gradle

dependencies {
    implementation 'com.snailcatch:snailcatch-sdk:0.1.29'
    ....

slowquery:
  repository-pointcut: execution(* com.core..repository.impl..*.*(..))

 

SDK 를 사용하는 사용자는 위와 같이 배포된 패키지를 추가하고 Repository 가 있는 포인트 컷을 application.yml 에 추가했습니다.

 

이후 API 를 쏴주면 아래와 같은 정보가 콘솔로그로 찍히고 있습니다. 실행 시간, 실행된 메서드 이름, 바인딩된 SQL 쿼리, 실행계획 등의 정보를 한눈에 볼 수 있습니다.

 

 

자! 여기까지 DB 로 쏘는 실제 SQL 쿼리를 추출하고 필요한 정보들을 모아 콘솔로그에 찍어주는 기능까지 만들어 봤습니다. 하지만 로그를 콘솔로만 찍어주고 있습니다. 

 

 

 

다음 작업은 수집한 쿼리 로그들을 어떤식으로 저장하고 관리할지에 대해 고민하려 합니다.

 

 

https://github.com/sinminseok/snail-catch

GitHub - sinminseok/snail-catch