목차 페이지로 이동

데이터 규모에 따른 JPA N+1 문제 진단과 해결 전략 비교
(Fetch Join, Entity Graph, Batch Fetching)

2. 성능 측정 방법론

2.1. 성능 측정 설계 개요

직접 개발한 API Path 중 N+1 문제가 두드러진 Path 1개 선정
해당 API Path에 대하여 4가지 버전을 준비
- Original : 프로젝트 종료 시점 상태 (일부 fetch join 적용됨)
- Pure : fetch join 및 리펙토링도 없는 순수 상태
- Optimized : fetch join 및 코드 리펙토링이 적용된 상태
- Graph : Optimized 버전과 동일하나 fetch join이 아닌 Entity Graph가 사용된 상태
테스트 데이터를 소규모 데이터와 대규모 데이터 2가지 버전으로 준비
테스트 케이스 3가지 준비
- Case 1
  - 소규모 데이터
  - 최대 동시 사용자 수 100명
  - hibernate default batch size = 0
- Case 2
  - 대규모 데이터
  - 최대 동시 사용자 수 100명
  - hibernate default batch size = 0
- Case 3
  - 대규모 데이터
  - 최대 동시 사용자 수 100명
  - hibernate default batch size = 100
각각의 테스트 케이스 별로 전체 종합 테스트를 진행
- P6Spy 쿼리 분석
- K6 부하 테스트
- GC 로그 분석
최종 결과 분석

2.2. 쿼리 분석 : Hibernate Statistics & P6Spy 로그 분석

(1)Hibernate Statistics & P6Spy 로깅

굳이 P6Spy를 활용한 이유

P6Spy는 각 쿼리의 실제 실행 시간을 밀리초 단위로 알 수 있다.
P6Spy는 JDBC 드라이버 수준에서 모든 데이터베이스 작업을 포착한다.
P6Spy는 각 쿼리가 어떤 데이터베이스 Connection을 통해 실행되었는지 알 수 있다.
바인딩된 파라미터 확인 (Hibernate로도 가능은 하다)

측정 지표

P6Spy 로그
- SQL 쿼리의 실제 실행 시간
- Connection ID
- 쿼리 유형
- 호출 경로
- SQL 쿼리

Hibernate Session별 통계
- 발생한 총 쿼리 수 (JDBC 문장 수)
- Connection 획득/반납 수
- 엔티티 플러시 수

커스텀 AOP 정보
- 메서드의 실행 시간
- 쿼리 수
- 지연 로딩 수

(2)측정 방법 및 설정

측정 방법

Hibernate Statistics와 P6Spy, 커스텀 마커 로깅을 통해 로그 출력을 설정한다.
- 커스텀 마커 로그로 각 API 호출에 해당하는 로그 구분
AOP로 모든 트랜잭션 메서드에 Hibernate Statistics 커스텀 로그를 추가한다.
- 메서드 실행 전후 변화를 관찰하기 위해서
4가지 버전을 차례로 호출한 후 로그를 통해 정보를 획득한다.
(Warm-up 호출 사전 실시)
Python 로그 분석기를 만들어서 로그를 분석한다.
- API 호출 전후 마커 사이의 P6Spy, Statistics 로그를 분석
- 버전 별 정보를 종합하고 결과를 분석하여 출력

build.gradle

implementation("org.springframework.boot:spring-boot-starter-data-jpa")
implementation("com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.9.0")

Hibernate Statistics와 P6Spy를 위한 필수 의존성이다.
P6Spy 의존성은 2 종류이고, 각각에 따라 설정 방법이 다르다. (설정을 잘못하면 이중 로그가 나올 수 있다)
'P6Spy 로그가 2번 찍히는 경우' 게시글로 이동
지금 설정한 방법은 spring.datasource 정보를 따로 바꿀 필요가 없다.

application.yml

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

logging:
  level:
    root: WARN
    org.hibernate.SQL: OFF
    org.hibernate.type.descriptor.sql.BasicBinder: TRACE
    API_LOGGER: INFO
    p6spy: DEBUG
    org.hibernate.stat: DEBUG
    org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: INFO
    org.springframework: WARN
  file:
    name: logs/application.log
  pattern:
    file: "%d{yyyy-MM-dd HH:mm:ss.SSS} | Level: %5p | Thread: %thread | Logger: %-40.40logger{39} | Message: %m%n"
    console: "%d{yyyy-MM-dd HH:mm:ss} - %msg%n"

커스텀 마커 인터셉터 설정

@Component
public class ApiLoggingInterceptor implements HandlerInterceptor {

  private static final Logger logger = LoggerFactory.getLogger("API_LOGGER");

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
    String method = request.getMethod();
    String uri = request.getRequestURI();
    String queryString = request.getQueryString();

    if (queryString != null) {
      uri += "?" + queryString;
    }

    logger.info("\n\u001B[32m========== API 호출 시작: " + method + " " + uri + " ==========\u001B[0m");
    request.setAttribute("startTime", System.currentTimeMillis());
    return true;
  }

  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
    Long startTime = (Long) request.getAttribute("startTime");
    if (startTime != null) {
      long executionTime = System.currentTimeMillis() - startTime;
      String method = request.getMethod();
      String uri = request.getRequestURI();

      logger.info("\u001B[32m========== API 호출 완료: " + method + " " + uri +
          " | 실행시간: " + executionTime + "ms | 상태코드: " + response.getStatus() + " ==========\u001B[0m\n");
    }
  }
}

WebMvcConfigurer 구현체에 만든 인터셉터를 등록해야 사용할 수 있다.

@Configuration
@RequiredArgsConstructor
public class CustomWebMvcConfig implements WebMvcConfigurer {

  private final LoginUserArgumentResolver loginUserArgumentResolver;
  private final ApiLoggingInterceptor apiLoggingInterceptor;
  private final GcLogInterceptor gcLogInterceptor;

  @Override
  public void addArgumentResolvers(List<HandlerMethodArgumentResolver> resolvers) {
    resolvers.add(loginUserArgumentResolver);
  }

  @Override
  public void addInterceptors(InterceptorRegistry registry) {
    registry.addInterceptor(apiLoggingInterceptor)
        .addPathPatterns("/api/**");

    registry.addInterceptor(gcLogInterceptor)
        .addPathPatterns("/api/v1/protections/**");
  }
}

P6Spy 로그 커스텀 설정

@Configuration
public class P6SpyConfig {

  @PostConstruct
  public void setLogMessageFormat() {
    // SimplifiedP6SpyFormatter or EnhancedP6SpyFormatter
    P6SpyOptions.getActiveInstance().setLogMessageFormat(EnhancedP6SpyFormatter.class.getName());
  }

  public static class EnhancedP6SpyFormatter implements MessageFormattingStrategy {

    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category,
        String prepared, String sql, String url) {
      if (sql == null || sql.trim().isEmpty()) {
        return "";
      }

      String stackInfo = extractStackInfo();

      return formatOutput(elapsed, category, sql, connectionId, stackInfo);
    }

    private String formatOutput(long elapsed, String category, String sql, int connectionId,
        String stackInfo) {
      StringBuilder output = new StringBuilder();

      output.append("[P6Spy] | ");
      output.append(String.format("%4dms", elapsed)).append(" | ");
      output.append("conn=").append(connectionId).append(" | ");
      output.append(category).append(" | ");

      if (!stackInfo.isEmpty()) {
        output.append(stackInfo).append(" | ");
      }

      if (category.equals("statement")) {
        String formattedSql = formatSql(sql);
        output.append(formattedSql);
      } else {
        output.append(sql);
      }

      return output.toString();
    }

    private String formatSql(String sql) {
      String formattedSql;

      // Apply different format based on SQL type
      if (isSelectQuery(sql)) {
        formattedSql = FormatStyle.BASIC.getFormatter().format(sql);
      } else if (isDDL(sql)) {
        formattedSql = FormatStyle.DDL.getFormatter().format(sql);
      } else {
        formattedSql = sql;
      }

      return formattedSql.replaceAll("\\s+", " ").trim();
    }

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

    private boolean isDDL(String sql) {
      String lowerSql = sql.trim().toLowerCase(Locale.ROOT);
      return lowerSql.startsWith("create") || lowerSql.startsWith("alter") || lowerSql.startsWith(
          "drop") || lowerSql.startsWith("truncate");
    }

    private String extractStackInfo() {
      StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
      StringBuilder callChain = new StringBuilder();

      for (StackTraceElement element : stackTrace) {
        String className = element.getClassName();
        if (className.startsWith("com.patrol") && !className.contains(
            "P6Spy") && !className.contains("Hibernate")) {

          if (callChain.length() > 0) {
            callChain.append(" -> ");
          }
          callChain.append(className).append(".").append(element.getMethodName()).append(":")
              .append(element.getLineNumber());
        }
      }

      return callChain.toString();
    }
  }
}

AOP 설정

@Aspect
@Component
@RequiredArgsConstructor
public class RepositoryQueryMonitor {

  private static final Logger logger = LoggerFactory.getLogger("API_LOGGER");
  private final EntityManagerFactory entityManagerFactory;

  @Around("@annotation(org.springframework.transaction.annotation.Transactional) || " +
      "@within(org.springframework.transaction.annotation.Transactional)")
  public Object logQueryCount(ProceedingJoinPoint joinPoint) throws Throwable {
    SessionFactory sessionFactory = entityManagerFactory.unwrap(SessionFactory.class);
    Statistics stats = sessionFactory.getStatistics();

    // 실행 전 통계
    long beforeQueries = stats.getQueryExecutionCount();
    long beforeCollections = stats.getCollectionFetchCount();
    long beforeEntities = stats.getEntityFetchCount();

    long beforeLazyLoads = stats.getEntityLoadCount();

    String fullClassName = joinPoint.getSignature().getDeclaringTypeName();
    String simpleClassName = fullClassName.substring(fullClassName.lastIndexOf(".") + 1);
    String methodName = simpleClassName + "." + joinPoint.getSignature().getName();

    long startTime = System.currentTimeMillis();
    Object result = joinPoint.proceed();
    long executionTime = System.currentTimeMillis() - startTime;

    // 실행 후 통계
    long afterQueries = stats.getQueryExecutionCount();
    long afterCollections = stats.getCollectionFetchCount();
    long afterEntities = stats.getEntityFetchCount();

    long afterLazyLoads = stats.getEntityLoadCount();

    // 변경된 통계 계산
    long queryCount = afterQueries - beforeQueries;
    long collectionFetchCount = afterCollections - beforeCollections;
    long entityFetchCount = afterEntities - beforeEntities;

    // Lazy 로딩 통계 계산
    long lazyLoadCount = afterLazyLoads - beforeLazyLoads;


    logger.info("\u001B[35m[{}()] | Execution time: {}ms | Queries: {} | Collections: {} | Entities: {} | Lazy Loads: {}\u001B[0m",
        methodName, executionTime, queryCount, collectionFetchCount, entityFetchCount,
        lazyLoadCount);

    return result;
  }
}

GC 로그 커스텀 설정

package com.patrol.global.webMvc;

import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;

import java.io.FileWriter;
import java.io.IOException;
import java.io.PrintWriter;
import java.time.OffsetDateTime;
import java.time.ZoneId;
import java.time.format.DateTimeFormatter;
import java.util.UUID;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

@Component
public class GcLogInterceptor implements HandlerInterceptor {

  // GC 로그 파일 경로
  @Value("${gc.log.file:gc_combined.log}")
  private String gcLogFile;

  private static final DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSZ")
      .withZone(ZoneId.systemDefault());

  private static final Pattern VERSION_PATTERN = Pattern.compile("/api/v1/protections/(?:([^/]+)/)?my-cases");


  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
    String method = request.getMethod();
    String uri = request.getRequestURI();
    String version = detectVersion(uri);


    String requestId = generateRequestId();   // API 고유 ID
    request.setAttribute("gcLogRequestId", requestId);

    // API 호출 시작 로그
    OffsetDateTime now = OffsetDateTime.now();
    appendToGcLog(String.format("[%s] GC_MARKER: API_START [%s] %s %s | RequestID: %s | ThreadID: %d",
        now.format(formatter), version, method, uri, requestId, Thread.currentThread().getId()));

    request.setAttribute("gcLogStartTime", System.currentTimeMillis());
    request.setAttribute("gcLogVersion", version);
    return true;
  }



  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
    Long startTime = (Long) request.getAttribute("gcLogStartTime");
    String version = (String) request.getAttribute("gcLogVersion");
    String requestId = (String) request.getAttribute("gcLogRequestId");

    if (startTime != null) {
      long executionTime = System.currentTimeMillis() - startTime;
      String method = request.getMethod();
      String uri = request.getRequestURI();

      // API 호출 종료 로그
      OffsetDateTime now = OffsetDateTime.now();
      appendToGcLog(String.format("[%s] GC_MARKER: API_END [%s] %s %s | 실행시간: %dms | 상태코드: %d | RequestID: %s | ThreadID: %d",
          now.format(formatter), version, method, uri, executionTime, response.getStatus(),
          requestId, Thread.currentThread().getId()));
    }
  }


  private String generateRequestId() {
    return UUID.randomUUID().toString().substring(0, 8);
  }


  private String detectVersion(String uri) {
    Matcher matcher = VERSION_PATTERN.matcher(uri);
    if (matcher.find()) {
      String versionPart = matcher.group(1);
      if (versionPart == null) {
        return "original";
      } else {
        return versionPart;
      }
    }
    return "unknown";
  }


  private synchronized void appendToGcLog(String message) {
    try (PrintWriter writer = new PrintWriter(new FileWriter(gcLogFile, true))) {
      writer.println(message);
    } catch (IOException e) {
      System.err.println("GC 로그 파일 쓰기 실패: " + e.getMessage());
    }
  }


  private String formatTimeForGcLog(OffsetDateTime time) {
    String formatted = time.format(DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSZ"));
    return formatted.replace("+09:00", "+0900");
  }
}

2.3. 부하 테스트 : K6 부하테스트

(1)K6 부하 테스트

시나리오 설명

사용자 로그인
단계적으로 가상 사용자 수를 증가시키며 API 엔드포인트를 호출
- 시작 : 5명의 동시 사용자로 10초간 진행
- 단계적 증가 : 20명 → 50명 → 100명으로 각 30초씩 증가
- 최대 부하 유지 : 100명의 사용자로 30초간 유지
- 마무리 : 5명으로 감소하여 10초간 진행

측정 지표

총 요청 수
테스트 기간 (초)
초당 트랜잭션 (TPS)
평균 응답 시간 (ms)
최소 응답 시간 (ms)
중앙값 응답 시간 (ms)
최대 응답 시간 (ms)
90 percentile 응답 시간 (ms)
95 percentile 응답 시간 (ms)
99 percentile 응답 시간 (ms)
99.9 percentile 응답 시간 (ms)
요청 실패율 (%)

(2)측정 방법 및 설정

측정 방법

4가지 버전에 대하여 K6 테스트 시나리오를 만든다. (VU : 100명)
K6 결과를 JSON 파일로 출력하도록 설정한다.
K6 결과를 Grafana로 출력하도록 설정한다.
K6 결과에 대하여 Grafana를 통해 그래프를 얻어 분석한다.

K6 테스트 시나리오

최대 동시 100명

import http from 'k6/http';
import { check, sleep } from 'k6';
import { Counter, Rate, Trend } from 'k6/metrics';

// 커스텀 메트릭
export const successRate = new Rate('success_rate');
export const requestsPerSecond = new Counter('requests_per_second');
export const requestDuration = new Trend('request_duration');

// 로그인 정보
const LOGIN_EMAIL = 'test3@test.com';
const LOGIN_PASSWORD = 'password3';

export function createOptions(apiVersion) {
    return {
        stages: [
            { duration: '10s', target: 5 },
            { duration: '30s', target: 20 },
            { duration: '30s', target: 50 },
            { duration: '30s', target: 100 },
            { duration: '30s', target: 100 },  // 최대 부하 유지
            { duration: '10s', target: 5 }
        ],
        thresholds: {
            http_req_duration: ['p(95)<600', 'p(99)<800'],  // 95%의 요청이 600ms 이내, 99%는 800ms 이내
            http_req_failed: ['rate<0.01'],                 // 오류율 1% 미만
        },
        tags: {
            api_version: apiVersion  // 전역 태그 추가
        },
        summaryTrendStats: ['avg', 'min', 'med', 'max', 'p(90)', 'p(95)', 'p(99)', 'p(99.9)', 'count'],
    };
}

export function setupTest(apiVersion) {
    console.log(`${apiVersion} 버전 테스트 시작...`);

    const loginUrl = 'http://localhost:8090/api/v2/auth/login';
    const loginPayload = JSON.stringify({
        email: LOGIN_EMAIL,
        password: LOGIN_PASSWORD,
        token: ''
    });

    const loginParams = {
        headers: { 'Content-Type': 'application/json' }
    };

    const loginResponse = http.post(loginUrl, loginPayload, loginParams);
    console.log('로그인 응답 상태:', loginResponse.status);

    check(loginResponse, {
        '로그인 성공': (r) => r.status === 200
    });

    if (loginResponse.status !== 200) {
        console.error('로그인 실패. 테스트를 중단합니다.');
        return null;
    }

    const allCookies = loginResponse.headers['Set-Cookie'] || '';
    const cookieValues = [];
    if (allCookies) {
        if (Array.isArray(allCookies)) {
            allCookies.forEach(cookie => {
                const parts = cookie.split(';');
                if (parts.length > 0) cookieValues.push(parts[0].trim());
            });
        } else {
            const cookies = allCookies.split(',');
            cookies.forEach(cookie => {
                const parts = cookie.split(';');
                if (parts.length > 0) cookieValues.push(parts[0].trim());
            });
        }
    }
    const cleanCookies = cookieValues.join('; ');

    return { cookies: cleanCookies };
}

export function getApiUrl(apiVersion) {
    const apiType = __ENV.API_TYPE || 'my-cases';

    if (apiType === 'my-cases') {
        if (apiVersion === 'original') {
            return 'http://localhost:8090/api/v1/protections/my-cases';
        } else if (apiVersion === 'pure') {
            return 'http://localhost:8090/api/v1/protections/pure/my-cases';
        } else if (apiVersion === 'optimized') {
            return 'http://localhost:8090/api/v1/protections/optimized/my-cases';
        } else if (apiVersion === 'graph') {
            return 'http://localhost:8090/api/v1/protections/graph/my-cases';
        }
    } else if (apiType === 'case-detail') {
        const caseId = __ENV.CASE_ID || '123';
        if (apiVersion === 'original') {
            return `http://localhost:8090/api/v1/protections/${caseId}`;
        } else if (apiVersion === 'pure') {
            return `http://localhost:8090/api/v1/protections/pure/${caseId}`;
        } else if (apiVersion === 'optimized') {
            return `http://localhost:8090/api/v1/protections/optimized/${caseId}`;
        } else if (apiVersion === 'graph') {
            return `http://localhost:8090/api/v1/protections/graph/${caseId}`;
        }
    }

    throw new Error(`Unknown API version: ${apiVersion} or API type: ${apiType}`);
}

export function runTest(apiVersion, cookies) {
    const url = getApiUrl(apiVersion);
    const apiType = __ENV.API_TYPE || 'my-cases';

    const expectedMessage = apiType === 'case-detail'
        ? "보호 희망 동물의 상세 조회 성공"
        : "내가 등록한 보호 희망 동물의 목록 조회 성공";

    const params = {
        headers: {
            'Cookie': cookies
        },
        tags: {
            api_version: apiVersion,
            endpoint: url
        }
    };

    const startTime = new Date().getTime();
    const response = http.get(url, params);
    const duration = new Date().getTime() - startTime;

    // 커스텀 메트릭 기록
    requestsPerSecond.add(1);
    requestDuration.add(duration);


    if (Math.random() < 0.01) {  // 1%의 확률로 상세 검증
        try {
            const responseBody = JSON.parse(response.body);
            console.log(`샘플 응답 검증 (${url}): ${responseBody.msg === expectedMessage ? '성공' : '실패'}`);
            if (responseBody.msg !== expectedMessage) {
                console.log(`예상 메시지: ${expectedMessage}, 실제 메시지: ${responseBody.msg}`);
            }
        } catch (e) {
            console.log(`샘플 응답 검증 실패 (${url}): JSON 파싱 오류`);
        }
    }

    const checkResult = check(response, {
        '상태 코드 200': (r) => r.status === 200,
        '응답 본문 존재': (r) => r.body && r.body.length > 0,
        '응답 형식 JSON': (r) => r.headers['Content-Type'] && r.headers['Content-Type'].includes('application/json'),
        '올바른 응답 메시지': (r) => {
            try {
                const body = JSON.parse(r.body);
                return body.msg === expectedMessage;
            } catch {
                return false;
            }
        }
    });

    successRate.add(checkResult);
    return response;
}

export function createSummary(data, apiVersion) {
    const totalRequests = data.metrics.http_reqs.values.count;
    const totalDuration = data.state.testRunDurationMs / 1000;
    const tps = totalRequests / totalDuration;

    console.log(`
=========================================================
            ${apiVersion} 버전 성능 테스트 결과 요약
=========================================================
총 요청 수: ${totalRequests}
테스트 기간: ${totalDuration}초
TPS (초당 트랜잭션): ${tps.toFixed(2)}

응답 시간 (ms):
  - 평균: ${data.metrics.http_req_duration.values.avg.toFixed(2)}
  - 최소: ${data.metrics.http_req_duration.values.min.toFixed(2)}
  - 중앙값: ${data.metrics.http_req_duration.values.med.toFixed(2)}
  - 최대: ${data.metrics.http_req_duration.values.max.toFixed(2)}
  - p90: ${data.metrics.http_req_duration.values["p(90)"].toFixed(2)}
  - p95: ${data.metrics.http_req_duration.values["p(95)"].toFixed(2)}
  - p99: ${data.metrics.http_req_duration.values["p(99)"].toFixed(2)}
  - p99.9: ${data.metrics.http_req_duration.values["p(99.9)"].toFixed(2)}

실패율: ${(data.metrics.http_req_failed.values.rate * 100).toFixed(2)}%
=========================================================
    `);

    // JSON 결과
    const jsonReport = {
        apiVersion: apiVersion,
        summary: {
            totalRequests: totalRequests,
            testDuration: totalDuration,
            tps: tps
        },
        responseTime: {
            avg: data.metrics.http_req_duration.values.avg,
            min: data.metrics.http_req_duration.values.min,
            med: data.metrics.http_req_duration.values.med,
            max: data.metrics.http_req_duration.values.max,
            p90: data.metrics.http_req_duration.values["p(90)"],
            p95: data.metrics.http_req_duration.values["p(95)"],
            p99: data.metrics.http_req_duration.values["p(99)"]
        },
        failRate: data.metrics.http_req_failed.values.rate,
        vus_max: data.metrics.vus_max.values.max,
        http_req_waiting: data.metrics.http_req_waiting.values.avg,
        http_req_connecting: data.metrics.http_req_connecting.values.avg,
        http_req_sending: data.metrics.http_req_sending.values.avg,
        http_req_receiving: data.metrics.http_req_receiving.values.avg
    };

    return {
        stdout: JSON.stringify(data.metrics, null, 4),
        [`./results/${apiVersion}-results.json`]: JSON.stringify(jsonReport, null, 4),
        [`./results/${apiVersion}-full-report.json`]: JSON.stringify(data, null, 4)
    };
}

각 버전별 실행 파일 예시

import { sleep } from 'k6';
import * as common from './k6-common-large.js';

const API_VERSION = 'optimized';

export const options = common.createOptions(API_VERSION);

export function setup() {
    return common.setupTest(API_VERSION);
}

export default function(data) {
    if (!data) return;

    const response = common.runTest(API_VERSION, data.cookies);
    sleep(0.5 + Math.random());
}

export function handleSummary(data) {
    return common.createSummary(data, API_VERSION);
}

2.4. 메모리 분석 : GC 로그 분석

(1)메모리 사용량 측정 : JVM GC 모니터링

GC 로그 측정 지표

GC 발생 횟수
- JVM이 가비지 컬렉션을 실행한 총 횟수
- 적을수록 좋으며, 많은 경우 메모리 할당/해제가 자주 발생한다는 의미
GC 이벤트별 소요 시간
- 각 GC 작업의 실제 소요 시간 (ms)
GC 이벤트별 시작/종료 메모리
- GC 전후의 메모리 사용량 (MB)
GC 유형 정보
- Young GC, Full GC 등 발생한 GC의 유형
GC 발생 시점
- 타임스탬프 정보
힙 메모리 총량
- 할당된 전체 힙 메모리 크기 (KB)
사용 중인 메모리
- 특정 시점에 사용 중인 메모리 양 (KB)

K6 결과로부터 가져오는 지표

API 요청 수
평균 API 응답 시간
최대 API 응답 시간
테스트 실행 기간

분석 지표

평균 GC 시간 (ms)
- 각 GC 작업이 소요한 시간의 평균값
- 애플리케이션 일시 정지 시간을 나타내므로 짧을수록 좋다
- 전체 GC 시간 ÷ GC 발생 횟수
최대 GC 시간 (ms)
- 가장 오래 걸린 GC 작업의 시간
- 가장 길었던 일시 정지 시간
- 모든 GC 이벤트 중 가장 긴 소요 시간
총 회수 메모리량 (MB)
- GC를 통해 회수된 전체 메모리 양
- 애플리케이션의 메모리 회수율
- 모든 GC에서 (GC 전 메모리 - GC 후 메모리)의 합
평균 메모리 회수량 (MB)
- 각 GC 작업당 회수한 평균 메모리 양
- GC 효율성을 측정하는 지표
- 총 회수 메모리량 ÷ GC 발생 횟수
GC 유형별 발생 횟수
- 다양한 GC 유형(Young, Old, Full GC 등)별 발생 횟수
- 메모리 사용 패턴 파악
평균 사용 메모리
- 모든 메모리 스냅샷의 평균
최대 사용 메모리
- 모든 메모리 스냅샷 중 최대값
평균 메모리 사용률
- (사용 중인 메모리 ÷ 힙 메모리 총량) × 100%
API 총 실행 시간
- API 호출 종료 시점 - 시작 시점의 합
API 평균 실행 시간
- API 총 실행 시간 ÷ API 요청 수
API 최대 실행 시간
- 모든 API 요청 중 가장 긴 실행 시간
요청당 GC 발생 비율
- GC 발생 횟수 ÷ API 요청 수
총 실행 시간 대비 GC 소요 시간 비율
- (GC 총 시간 ÷ API 총 실행 시간) × 100%
요청당 메모리 회수량
- 총 회수 메모리량 ÷ API 요청 수

(2)측정 방법 및 설정

측정 방법

JVM 옵션과 커스텀 로깅을 통해 GC 로그를 획득한다.
- API 호출 전후 마커용 API를 만들어 추출할 로그의 범위 설정
시작 마커 API 호출 ⇒ K6 부하 테스트 ⇒ 종료 마커 API 호출 (4가지 버전 반복)
Python GC 로그 분석기를 만들어 분석한다.
- K6 테스트로 총 API 호출 수 등의 정보를 얻어낸다.
- GC Log와 함께 각 API의 효율성 분석 실시

JVM 옵션 설정

-XX:+UseG1GC -Xlog:gc*=debug:file=logs/gc_combined.log:time,uptime,level,tags -Dgc.log.file=logs/gc_combined.log

K6 테스트 전후 API 호출로 마커 설정

@RestController
@RequestMapping("/api/v1/gc-test")
public class ApiV1GcTestController {

  @Value("${gc.log.file:gc_combined.log}")
  private String gcLogFile;

  @PostMapping("/start-test")
  public ResponseEntity<String> startTest(@RequestParam String version) {
    try {
      new FileWriter(gcLogFile, false).close();

      String timestamp = OffsetDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSXXX"));
      String startMarker = String.format("[%s] GC_MARKER: K6_TEST_START [%s]", timestamp, version);

      try (BufferedWriter writer = new BufferedWriter(new FileWriter(gcLogFile, true))) {
        writer.write(startMarker);
        writer.newLine();
        writer.flush();
      }

      return ResponseEntity.ok("GC 로그 초기화 및 테스트 시작 마커가 추가되었습니다.");
    } catch (IOException e) {
      return ResponseEntity.status(HttpStatus.INTERNAL_SERVER_ERROR)
          .body("로그 파일 작업 실패: " + e.getMessage());
    }
  }


  @PostMapping("/end-test")
  public ResponseEntity<String> endTest(@RequestParam String version) {
    try {
      String timestamp = OffsetDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd'T'HH:mm:ss.SSSXXX"));
      String endMarker = String.format("[%s] GC_MARKER: K6_TEST_END [%s]", timestamp, version);

      try (BufferedWriter writer = new BufferedWriter(new FileWriter(gcLogFile, true))) {
        writer.write(endMarker);
        writer.newLine();
        writer.flush();
      }

      return ResponseEntity.ok("테스트 종료 마커가 추가되었습니다.");
    } catch (IOException e) {
      return ResponseEntity.status(HttpStatus.INTERNAL_SERVER_ERROR)
          .body("로그 파일 작업 실패: " + e.getMessage());
    }
  }
}

로그 분석 시 분석할 로그 범위를 지정하기 위함이다.

K6 전후 커스텀 로그 예시

[2025-04-17T20:19:00.886+09:00] GC_MARKER: K6_TEST_START [pure]
[2025-04-17T20:19:00.892+0900][6001.565s][debug][gc,task,start     ] G1 Service Thread (Periodic GC Task) (run 0.002ms after schedule)
[2025-04-17T20:19:00.892+0900][6001.565s][debug][gc,task           ] G1 Service Thread (Periodic GC Task) (run: 0.111ms) (cpu: 0.000ms)

API 전후 커스텀 로그 예시

[2025-05-02T14:44:35.546+0900][10843.544s][info ][gc                ] GC(3537) Pause Young (Normal) (G1 Evacuation Pause) 461M->130M(560M) 8.677ms
[2025-05-02T14:44:35.546+0900][10843.544s][info ][gc,cpu            ] GC(3537) User=0.00s Sys=0.00s Real=0.01s
[2025-05-02T14:44:35.546+0900][10843.544s][debug][gc,task           ] G1 Service Thread (Card Set Free Memory Task) (run: 4.856ms) (cpu: 0.000ms)
[2025-05-02T14:44:35.546+0900][10843.545s][debug][gc,refine         ] Concurrent refinement: wanted 0, cards: 456, predicted: 915, time: 482.66ms
[2025-05-02T14:44:35.547+0900] GC_MARKER: API_END [graph] GET /api/v1/protections/graph/my-cases | 실행시간: 85ms | 상태코드: 200 | RequestID: 841f0a23 | ThreadID: 110472
[2025-05-02T14:44:35.549+0900] GC_MARKER: API_START [graph] GET /api/v1/protections/graph/my-cases | RequestID: 6993c4a4 | ThreadID: 110479
[2025-05-02T14:44:35.578+0900] GC_MARKER: API_START [graph] GET /api/v1/protections/graph/my-cases | RequestID: b785a418 | ThreadID: 110480

다음 페이지로 이동 (3. 테스트 환경 및 조건)

데이터 규모에 따른 JPA N+1 문제 진단과 해결 전략 비교 (Fetch Join, Entity Graph, Batch Fetching)

(1)Hibernate Statistics & P6Spy 로깅

굳이 P6Spy를 활용한 이유

측정 지표

(2)측정 방법 및 설정

측정 방법

build.gradle

application.yml

커스텀 마커 인터셉터 설정

P6Spy 로그 커스텀 설정

AOP 설정

GC 로그 커스텀 설정

(1)K6 부하 테스트

시나리오 설명

측정 지표

(2)측정 방법 및 설정

측정 방법

K6 테스트 시나리오

(1)메모리 사용량 측정 : JVM GC 모니터링

GC 로그 측정 지표

K6 결과로부터 가져오는 지표

분석 지표

(2)측정 방법 및 설정

측정 방법

JVM 옵션 설정

K6 테스트 전후 API 호출로 마커 설정

K6 전후 커스텀 로그 예시

API 전후 커스텀 로그 예시

데이터 규모에 따른 JPA N+1 문제 진단과 해결 전략 비교
(Fetch Join, Entity Graph, Batch Fetching)