N+1 쿼리 감지 시스템 구축 후기 (MSA 환경 중심)

devty·2025년 7월 29일
JPASpringbootmsa

SpringBoot

목록 보기
11/11

1. 서론: MSA에서 N+1 쿼리가 더 위험한 이유

  • N+1 쿼리는 한 번의 논리적 요청이 수십, 수백 개의 데이터베이스 쿼리로 폭발하는 현상을 말합니다.
  • 주로 ORM(Object-Relational Mapping)의 지연 로딩(Lazy Loading) 때문에 발생하며, 불필요한 네트워크 왕복과 데이터베이스 부하 증가로 이어지죠.
  • 모놀리식 애플리케이션에서도 N+1은 문제지만, MSA에서는 그 파급 효과가 훨씬 큽니다.
  • 여러 마이크로서비스 간 통신이 빈번하고 각 서비스가 자체 DB를 가지는 경우가 많아, 특정 서비스의 N+1 쿼리가 다른 서비스의 지연으로 이어지거나 DB 부하를 가중시켜 연쇄적인 장애를 유발할 수 있습니다.
  • 이러한 MSA 환경의 N+1 문제를 실시간으로 감지하고, 개발 단계부터 효율적인 해결책을 찾는 것이 목표였습니다.

2. N+1 쿼리 감지 시스템 설계 및 구축 (MSA 특화)

  • 각 마이크로서비스 내 gRPC 인터셉터를 중심으로 Hibernate 쿼리 로깅 기능을 활용하는 분산 아키텍처를 구축했습니다.
  • 쿼리 모니터링은 비즈니스 로직과 독립적인 횡단 관심사이므로, 이를 common-query-monitor라는 별도 공통 모듈로 분리하여 모든 마이크로서비스가 이 모듈을 의존하도록 설계했습니다.

2.1. 프로젝트 모듈 구조

/your-msa-project-root
├── common-query-monitor/
│   ├── build.gradle.kts
│   └── src/main/kotlin/
│       └── com/yourcompany/common/querymonitor/
│           ├── config/
│           │   ├── GrpcServerConfig.kt
│           │   └── QueryMonitorProperties.kt
│           │
│           ├── db/
│           │   └── jpa/
│           │       ├── inspector/
│           │       │   ├── JpaInspector.kt
│           │       │   ├── QueryMetrics.kt
│           │       │   └── QueryMetricsManager.kt
│           │       └── aspect/
│           │           ├── JpaQueryExecutionTimeAspect.kt
│           │           └── JpaQueryExecutionTimeDto.kt
│           │
│           └── nplusone/
│               ├── interceptor/
│               │   └── NPlusOneGrpcDetectInterceptor.kt
│               ├── dto/
│               │   └── NPlusOneSuspiciousDto.kt
│               └── NPlusOneLogFormatter.kt
│
├── your-microservice-A/
│   ├── build.gradle.kts
│   └── src/main/kotlin/
│       └── com/yourcompany/servicea/
│           └── application/
│               └── ServiceAApplication.kt
│           └── resources/
│               └── application.yml (여기에 설정 추가)
│
└── settings.gradle.kts

2.2. 핵심 컴포넌트 역할 및 코드

  • GrpcServerConfig

    • gRPC 서버 설정을 담당하는 Spring @Configuration 클래스입니다.

    • 이 클래스에서 JpaInspector, QueryMetricsManager, NPlusOneLogFormatter, NPlusOneGrpcDetectInterceptor 등의 핵심 컴포넌트들을 Spring 빈으로 등록하여 의존성 주입이 가능하도록 합니다.

    • 또한, @GrpcGlobalServerInterceptor 어노테이션을 사용하여 NPlusOneGrpcDetectInterceptor가 모든 gRPC 서비스 호출에 자동으로 적용되도록 합니다.

      @Configuration
class GrpcServerConfig {

    @EventListener
    fun onServerStarted(event: GrpcServerStartedEvent) {
        log.info("gRPC Server started, services: ${event.server.services[0].methods}")
    }

    companion object {
        private val log = LoggerFactory.getLogger(GrpcServerConfig::class.java)
    }

    @Bean
    fun jpaInspector(queryMetricsManager: QueryMetricsManager): JpaInspector {
        return JpaInspector(queryMetricsManager)
    }

    @Bean
    fun hibernatePropertiesCustomizer(jpaInspector: JpaInspector): HibernatePropertiesCustomizer {
        return HibernatePropertiesCustomizer { props ->
            props["hibernate.session_factory.statement_inspector"] = jpaInspector
        }
    }

    @Bean
    @GrpcGlobalServerInterceptor
    fun nPlusOneGrpcDetectInterceptor(
        queryMetricsManager: QueryMetricsManager,
        nPlusOneLogFormatter: NPlusOneLogFormatter,
        properties: QueryMonitorProperties // QueryMonitorProperties를 빈으로 주입
    ): NPlusOneGrpcDetectInterceptor {
        return NPlusOneGrpcDetectInterceptor(queryMetricsManager, nPlusOneLogFormatter, properties)
    }
}
  • QueryMonitorProperties

    • 쿼리 모니터링 관련 모든 설정 값(슬로우 쿼리 임계값, N+1 최소 카운트 등)을 한곳에 모아 관리하는 Configuration Properties 클래스입니다.

    • @ConfigurationProperties를 사용하여 application.yml의 logging.query-monitor 접두사와 매핑됩니다.

    • @Value를 여러 번 사용하는 대신 이 객체를 주입받아 사용합니다.

      @Component
@ConfigurationProperties(prefix = "logging.query-monitor")
data class QueryMonitorProperties(
    val slowQueryThreshold: Long = 50L,
    val useLogging: Boolean = true,
    val nPlusOneMinCount: Int = 2
)
  • JpaInspector

    • Hibernate의 StatementInspector 인터페이스를 구현하여 JPA/Hibernate가 실제로 데이터베이스에 SQL 쿼리를 실행하기 직전에 이를 가로챕니다.

    • QueryMetricsManager를 주입받아 현재 스레드의 QueryMetrics에 SELECT SQL 쿼리를 기록하는 역할만 합니다.

      @Component
class JpaInspector(private val queryMetricsManager: QueryMetricsManager) : StatementInspector {
    override fun inspect(sql: String): String {
        val queryMetrics = queryMetricsManager.getCurrentMetrics()
        if (queryMetrics != null && sql.lowercase().startsWith("select")) {
            queryMetrics.appendQuery(sql)
        }
        return sql
    }
}
  • QueryMetrics

    • 단일 요청 스코프 내에서 실행된 SQL 쿼리의 개수와 시작 시간을 기록하는 데이터 클래스입니다.

    • 특정 요청 동안 발생한 쿼리 통계를 집계하는 데 사용됩니다.

      data class QueryMetrics(
    val startTime: Long = System.currentTimeMillis(),
    val sqlQueryCounts: MutableMap<String, Int> = ConcurrentHashMap()
) {
    fun appendQuery(sql: String) {
        sqlQueryCounts.compute(sql) { _, count -> (count ?: 0) + 1 }
    }
}
  • QueryMetricsManager

    • ThreadLocal을 사용하여 현재 요청 스레드에 QueryMetrics 객체를 저장하고, 검색하며, 제거하는 역할을 담당하는 매니저 클래스입니다.

    • JpaInspector와 NPlusOneGrpcDetectInterceptor가 QueryMetrics의 생명주기를 직접 관리하는 대신, 이 매니저를 통해 안전하게 접근하도록 변경되었습니다.

      @Component
class QueryMetricsManager {
    private val threadLocal = ThreadLocal<QueryMetrics>()

    fun start() {
        threadLocal.set(QueryMetrics())
    }

    fun clear() {
        threadLocal.remove()
    }

    fun getCurrentMetrics(): QueryMetrics? {
        return threadLocal.get()
    }
}
  • JpaQueryExecutionTimeAspect

    • Spring AOP를 사용하여 모든 Spring Data JPA Repository 메서드의 실행을 가로채고, 그 실행 시간을 측정합니다.

    • 설정된 임계값을 초과하는 경우 슬로우 쿼리로 간주하고 JpaQueryExecutionTimeDto를 사용하여 로그를 출력합니다.

    • 설정 값은 QueryMonitorProperties에서 가져옵니다.

      @Aspect
@Component
class JpaQueryExecutionTimeAspect(private val properties: QueryMonitorProperties) {

    private val log: Logger = LoggerFactory.getLogger(JpaQueryExecutionTimeAspect::class.java)

    @Around("execution(* org.springframework.data.repository.Repository+.*(..))")
    fun aroundQueryExecution(joinPoint: ProceedingJoinPoint): Any? {
        val startTime = System.currentTimeMillis()
        val result = joinPoint.proceed()
        val endTime = System.currentTimeMillis()
        val executionTime = endTime - startTime

        if (properties.useLogging && executionTime >= properties.slowQueryThreshold) {
            log.info("{}", JpaQueryExecutionTimeDto(
                queryMethod = joinPoint.signature.toShortString(),
                executionTime = executionTime
            ))
        }
        return result
    }
}
  • JpaQueryExecutionTimeDto

    • JPA Repository 메서드의 실행 시간을 로깅할 때 사용되는 데이터 전송 객체 (DTO)입니다.

    • 슬로우 쿼리 로그의 가독성을 높입니다.

      data class JpaQueryExecutionTimeDto(
    val queryMethod: String,
    val executionTime: Long
) {
    override fun toString(): String {
        return "슬로우 쿼리 감지: [메서드='${queryMethod}', 실행 시간=${executionTime}ms]"
    }
}
  • NPlusOneGrpcDetectInterceptor

    • gRPC 요청을 가로채서 N+1 쿼리 패턴을 감지하는 핵심 gRPC 서버 인터셉터입니다.

    • 요청 시작 시 QueryMetricsManager를 통해 쿼리 메트릭 수집을 시작하고, 요청이 완료되거나 취소될 때 수집된 메트릭을 기반으로 N+1 쿼리 여부를 판단하여 NPlusOneLogFormatter를 통해 상세 로그를 출력합니다.

    • 설정 값은 QueryMonitorProperties에서 가져옵니다.

      @Component
class NPlusOneGrpcDetectInterceptor(
    private val queryMetricsManager: QueryMetricsManager,
    private val nPlusOneLogFormatter: NPlusOneLogFormatter,
    private val properties: QueryMonitorProperties
) : ServerInterceptor {

    companion object {
        private val log: Logger = LoggerFactory.getLogger(NPlusOneGrpcDetectInterceptor::class.java)
    }

    override fun <ReqT, RespT> interceptCall(
        call: ServerCall<ReqT, RespT>,
        headers: Metadata,
        next: ServerCallHandler<ReqT, RespT>
    ): ServerCall.Listener<ReqT> {

        queryMetricsManager.start()

        val listener = next.startCall(call, headers)

        return object : ForwardingServerCallListener.SimpleForwardingServerCallListener<ReqT>(listener) {
            override fun onComplete() {
                val methodName = call.methodDescriptor.fullMethodName
                val metrics = queryMetricsManager.getCurrentMetrics()

                if (metrics != null) {
                    val duration = System.currentTimeMillis() - metrics.startTime
                    val sqlQueryCounts = metrics.sqlQueryCounts
                    logNPlusOneSuspiciousApi(methodName, duration, sqlQueryCounts)
                }

                queryMetricsManager.clear()
                super.onComplete()
            }

            override fun onCancel() {
                queryMetricsManager.clear()
                super.onCancel()
            }
        }
    }

    private fun logNPlusOneSuspiciousApi(apiMethod: String, duration: Long, sqlQueryCounts: Map<String, Int>) {
        if (sqlQueryCounts.any { (_, count) -> count >= properties.nPlusOneMinCount }) {
            val dto = NPlusOneSuspiciousDto(
                apiMethod = apiMethod,
                duration = duration,
                sqlQueryCounts = sqlQueryCounts
            )
            log.warn("N + 1이 의심되는 gRPC API 정보: {}", nPlusOneLogFormatter.format(dto))
        }
    }
}
  • NPlusOneSuspiciousDto

    • N+1 쿼리 감지 시 로그에 포함될 상세 데이터를 담는 데이터 클래스입니다.

    • 순수한 데이터만 담고 toString()은 객체 자체의 간략한 표현만 제공합니다.

    • 상세 로깅 포맷팅은 NPlusOneLogFormatter로 분리되었습니다.

      data class NPlusOneSuspiciousDto(
    val apiMethod: String,
    val duration: Long,
    val sqlQueryCounts: Map<String, Int>,
    val totalQueries: Int = sqlQueryCounts.values.sum()
) {
    override fun toString(): String {
        return "N+1 Suspicious [API='$apiMethod', Duration=$duration ms, TotalQueries=$totalQueries, QueryCountMapSize=${sqlQueryCounts.size}]"
    }
}
  • NPlusOneLogFormatter

    • NPlusOneSuspiciousDto 객체를 입력받아 N+1 쿼리 의심 상황에 대한 상세한 로그 메시지를 포맷팅하여 반환하는 클래스입니다.

    • 쿼리가 몇 번 반복되었는지, 쿼리 타입별 호출 횟수 등의 정보를 보기 좋게 구성합니다.

    • 이 클래스 덕분에 NPlusOneSuspiciousDto는 데이터 역할에만 집중할 수 있습니다.

      @Component
class NPlusOneLogFormatter {

    fun format(dto: NPlusOneSuspiciousDto): String {
        return buildString {
            append("N+1 의심: [API='").append(dto.apiMethod).append("', ")
            append("Duration=").append(dto.duration).append("ms, ")
            append("TotalQueries=").append(dto.totalQueries).append("]\n")

            val queryTypeCounts = mutableMapOf<String, Int>()
            dto.sqlQueryCounts.forEach { (query, count) ->
                val type = getQueryType(query)
                queryTypeCounts.compute(type) { _, currentCount -> (currentCount ?: 0) + count }
            }
            if (queryTypeCounts.isNotEmpty()) {
                append("  쿼리 타입별 호출 횟수:\n")
                queryTypeCounts.forEach { (type, count) ->
                    append("    - ").append(type).append(": ").append(count).append("회\n")
                }
            }

            if (dto.sqlQueryCounts.isNotEmpty()) {
                append("  반복 쿼리 목록 (${dto.sqlQueryCounts.size}개):\n")
                dto.sqlQueryCounts.forEach { (query, count) ->
                    append("    - [호출 ").append(count).append("회] ").append(query.trim()).append("\n")
                }
            } else {
                append("  반복된 쿼리가 감지되지 않았습니다.\n")
            }
        }
    }

    private fun getQueryType(sql: String): String {
        val trimmedSql = sql.trim().uppercase()
        return when {
            trimmedSql.startsWith("SELECT") -> "SELECT"
            trimmedSql.startsWith("INSERT") -> "INSERT"
            trimmedSql.startsWith("UPDATE") -> "UPDATE"
            trimmedSql.startsWith("DELETE") -> "DELETE"
            else -> "OTHER"
        }
    }
}
  • application.yml

    • 각 마이크로서비스의 리소스 폴더에 위치하며, 애플리케이션의 동작을 구성하는 설정 파일입니다.

    • Hibernate의 SQL 로깅 설정과 함께, QueryMonitorProperties에 매핑되는 logging.query-monitor 섹션을 포함합니다.

      # your-microservice-A/src/main/resources/application.yml

spring:
  jpa:
    properties:
      hibernate:
        show_sql: true # 개발 환경에서 SQL 쿼리 로그를 보기 위해 true로 설정
        format_sql: true # SQL 쿼리 로그를 보기 좋게 포맷팅
        session_factory:
          events:
            log:
              # Hibernate 자체의 슬로우 쿼리 로깅 임계값 (밀리초).
              # 우리 시스템의 JpaQueryExecutionTimeAspect와는 별개로 Hibernate가 자체적으로 로깅합니다.
              LOG_QUERIES_SLOWER_THAN_MS: 10 # 10ms보다 느린 쿼리는 Hibernate가 로깅

logging:
  level:
    # Hibernate의 SQL 쿼리 로그 레벨 설정 (DEBUG로 하면 모든 쿼리 출력, INFO는 슬로우 쿼리만)
    org.hibernate.SQL: DEBUG # 모든 SQL 쿼리를 콘솔에 출력 (디버깅 목적)
    org.hibernate.SQL_SLOW: INFO # Hibernate의 슬로우 쿼리 로그 레벨
    # N+1 및 슬로우 쿼리 감지 시스템의 로깅 레벨 (yourcompany.common.querymonitor 패키지 전체)
    com.yourcompany.common.querymonitor: DEBUG # 또는 INFO, WARN 등 적절한 레벨 설정

  # QueryMonitorProperties에 매핑될 설정들
  query-monitor:
    slow-query-threshold: 50 # JpaQueryExecutionTimeAspect가 감지할 슬로우 쿼리 임계값 (ms)
    use-logging: true        # 쿼리 모니터링 로깅 활성화 여부
    n-plus-one-min-count: 2  # NPlusOneGrpcDetectInterceptor가 N+1로 의심할 쿼리 반복 최소 횟수

3. 결과

  • 위 결과 사진을 보면 다음과 같은 정보들이 들어있다.
    • gRPC 엔드포인트
    • 총 SELET 수
    • 반복된 SELET
  • 따라서 해당 gRPC 기준으로 몇번 동일한 쿼리가 나왔는지 보고 개선을 진행하면 된다.

4. 시스템 운영 및 모니터링 (MSA 환경)

  • 구축된 N+1 쿼리 감지 시스템은 MSA 환경에서 다음 방식으로 운영 및 모니터링됩니다.
    • 중앙 집중식 로깅
      • 각 마이크로서비스에서 발생하는 N+1 및 슬로우 쿼리 로그를 Grafana Loki, Promtail, ELK 스택 등과 같은 중앙 집중식 로그 시스템으로 수집합니다.
      • 통합 대시보드를 통해 전체 MSA 시스템의 쿼리 성능을 모니터링하고 알림을 설정합니다.
    • 지속적인 피드백 루프
      • 감지된 문제를 개발팀에 즉시 피드백하여 지속적인 성능 개선과 코드 리팩토링을 유도합니다.
profile
devty
지나가는 개발자
이전 포스트

유틸리티 함수를 정적에서 인스턴스로 변경한 이유

0개의 댓글