Skip to content

[3차 과제] 성능 테스트 돌려보기 #164

New issue
New issue
Open
Open
[3차 과제] 성능 테스트 돌려보기#164
Assignees
yeeun0702choyeongju
Labels
3차docs 📃
@choyeongju

Description

@choyeongju
choyeongju
opened on Jan 24, 2025

Image

TODO

  1. 성능 테스트 돌려보기 (vuser 에 따른 성능 조사)
  2. 성능 개선해보기 만약 한다면, 실제 수치 기반 결과 작성 필요
  3. 성능 개선 간에, 다양한 기술 시도해보기

 

🍞 성능 테스트란 ?

애플리케이션, 시스템 또는 네트워크가 ‘특정 부하 조건 하에서 얼마나 잘 동작하는지’ 평가하는 소프트웨어 테스트의 한 유형을 성능테스트라고 한다. 우리는 속도, 안정성, 확장성, 처리량 등을 테스트하기 위해 성능테스트를 진행한다 !

 

🍞 성능 테스트 준비

1️⃣ 성능 테스트 도구 선택

AOP와 필터를 활용해 API 요청의 대기 시간(Wait Time)과 처리 시간(Compute Time)을 측정하여 병목현상을 식별하려고 한다.

2️⃣ 테스트 시나리오 정의

  • 요청 흐름
    • 클라이언트가 서버로 요청을 보냄.
    • WaitTimeLoggingFilter:
      • 요청이 애플리케이션에 도달한 시점의 시간을 기록.
      • requestStartTime 속성을 HttpServletRequest에 저장.
    • PerformanceAspect:
      • AOP가 특정 API 메서드를 감싸 실행.
      • 요청의 대기 시간과 처리 시간을 계산하여 로그로 출력.
  • 시간 측정 계산
    • Wait Time: computeStartTime - requestStartTime
    • Compute Time: computeEndTime - computeStartTime

3️⃣ 테스트 환경 구성
실제 운영 환경과 최대한 유사하게 준비하고 싶었으나, 배포환경에서 성능테스트를 진행하지 못하고 로컬에서 진행하게 되었다.

4️⃣ (이후) 가상 사용자(VUser) 설정

VUser(Virtual User)는 동시 사용자 수를 시뮬레이션하기 위한 단위를 의미한다.
우리는 점진적으로 VUser 수를 늘리며 성능 한계를 파악하려고 한다.
예시 ) VUser 50 → 100 → 200 → 500 → 1000

 

🍞 성능 테스트 실행

1️⃣ Wait Time 및 Compute Time 측정

  • AOP를 활용하여 요청 처리 시간을 측정했다.
    • Compute Time: API 실행 및 데이터베이스 쿼리와 같은 실제 처리 시간 : 처리 종료 시간 (computeEndTime) - 처리 시작 시간 (computeStartTime)
    • Wait Time: 요청이 서버에서 대기한 시간 : 요청 도착 시간 (requestStartTime) - 처리 시작 시간 (computeStartTime)

▶️ PerformanceAspect.java

package com.sopt.bbangzip.domain.subject.service;

import jakarta.servlet.http.HttpServletRequest;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Aspect
@Component
public class PerformanceAspect {

    private static final Logger logger = LoggerFactory.getLogger(PerformanceAspect.class);
    private final HttpServletRequest request;

    public PerformanceAspect(HttpServletRequest request) {
        this.request = request; // HttpServletRequest 주입
    }

    @Around("execution(* com.sopt.bbangzip.domain.subject.api.controller.SubjectController.getSubjectsBySemester(..))")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        long computeStartTime = System.nanoTime(); // Compute Time 시작

        // Wait Time 계산
        long requestStartTime = (long) request.getAttribute("requestStartTime");
        long waitTime = computeStartTime - requestStartTime;

        Object result;
        try {
            result = joinPoint.proceed(); // 실제 API 호출
        } catch (Throwable throwable) {
            logger.error("Exception in method: {}", joinPoint.getSignature(), throwable);
            throw throwable;
        }

        long computeEndTime = System.nanoTime(); // Compute Time 종료
        long computeTime = computeEndTime - computeStartTime;

        // 로그 출력
        logger.info("API [{}] Wait Time: {} ms, Compute Time: {} ms",
                joinPoint.getSignature(),
                waitTime / 1_000_000.0,  // 나노초를 밀리초로 변환
                computeTime / 1_000_000.0
        );

        return result;
    }
}

▶️ WaitTimeLoggingFilter.java

package com.sopt.bbangzip.domain.subject.service;

import jakarta.servlet.Filter;
import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletRequest;
import jakarta.servlet.ServletResponse;
import jakarta.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class WaitTimeLoggingFilter implements Filter {

    private static final Logger logger = LoggerFactory.getLogger(WaitTimeLoggingFilter.class);

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) {
        if (request instanceof HttpServletRequest) {
            long requestStartTime = System.nanoTime(); // 요청 시작 시간 기록
            request.setAttribute("requestStartTime", requestStartTime); // Attribute로 저장
        }

        try {
            chain.doFilter(request, response); // 요청 처리
        } catch (Exception e) {
            logger.error("Error in WaitTimeLoggingFilter: ", e);
        }
    }
}

▶️ logback-spring.xml

<configuration>
    <!-- 콘솔 로그 설정 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- 전체 애플리케이션 로그 파일 -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/application.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logs/application.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- 성능 로그 파일 -->
    <appender name="PERFORMANCE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/performance.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logs/performance.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- 로깅 레벨 설정 -->
    <logger name="com.sopt.bbangzip.domain.subject.service.PerformanceAspect" level="debug" additivity="false">
        <appender-ref ref="PERFORMANCE" />
    </logger>

    <!-- 루트 로거 -->
    <root level="info">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>
</configuration>

 

🍞 성능 테스트 결과 분석

우선, 클라이언트 사장님들과 배포환경에서 계속 소통이 이루어지고 있었기 때문에 로컬 환경에서만 성능테스트를 진행했다. 따라서 단일 요청에서 확인할 수 있는 내용들만 확인했다 !

 

🥪 단일 요청에서 확인할 수 있었던 내용들

  1. API 처리 성능
  • Compute Time 은 해당 API가 요청을 실제로 처리하는 데 걸린 시간을 의미하고 이를 통해 API의 성능 병목이 있는지 확인할 수 있었다.
  1. Foreign Key와 같은 스키마 변경 작업
  2. Hibernate 초기화 및 엔티티 매핑
  3. JWT 인증 필터에서 토큰 처리
  4. Tomcat 및 Spring DispatcherServlet 초기화

1~4번까지의 작업들이 Compute Time 과 연관이 있다.

JPA EntityManager 초기화

2025-01-24 23:02:04 [restartedMain] INFO  o.s.o.j.LocalContainerEntityManagerFactoryBean - Initialized JPA EntityManagerFactory for persistence unit 'default'

JWT 인증 필터 작업

token: eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzUxMiJ...
claim: {iat=1736922139, exp=1738131739, uid=1}

Hibernate Query 관련 작업

WARN  org.hibernate.orm.deprecation - MySQLDialect does not need to be specified explicitly...
INFO  o.hibernate.orm.connections.pooling - Database info:

HQL 파서 사용 가능 여부 확인

INFO  o.s.d.j.r.query.QueryEnhancerFactory - Hibernate is in classpath; If applicable, HQL parser will be used.

Tomcat 및 DispatcherServlet 초기화

2025-01-24 23:02:09 [restartedMain] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat started on port 8080 (http) with context path '/'
2025-01-24 23:02:12 [RMI TCP Connection(3)-192.168.98.1] INFO  o.s.web.servlet.DispatcherServlet - Completed initialization in 2 ms

 

  1. Spring Boot 초기화 시간
  • Spring Boot Application Context 초기화: Root WebApplicationContext 초기화 완료까지 약 2.8초 소요.
2025-01-24 23:02:01 [restartedMain] INFO  o.s.b.w.s.c.ServletWebServerApplicationContext - Root WebApplicationContext: initialization completed in 2829 ms
  • Hibernate 초기화: 엔티티 매핑, 데이터베이스 테이블 생성 등 ORM 초기화 작업 완료.
2025-01-24 23:02:01 [restartedMain] INFO  org.hibernate.Version - HHH000412: Hibernate ORM core version 6.6.4.Final
  • Tomcat 서버 시작: 포트 8080에서 서버가 시작되며, 약 7초 내외 소요.
2025-01-24 23:02:09 [restartedMain] INFO  o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-8080"]
2025-01-24 23:02:09 [restartedMain] INFO  o.s.b.w.e.tomcat.TomcatWebServer - Tomcat started on port 8080 (http) with context path '
  • 전체 애플리케이션 시작 완료: 약 15.6초에 걸쳐 모든 초기화 작업 완료 process running for 16.495
2025-01-24 23:02:11 [restartedMain] INFO  c.sopt.bbangzip.BbangzipApplication - Started BbangzipApplication in 15.629 seconds (process running for 16.495)
2025-01-24 23:02:12 [RMI TCP Connection(3)-192.168.98.1] INFO  o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet'

 

3 SQL 쿼리 성능

원본 쿼리에 대해서 먼저 살펴 본 다음, 어떤 부분에서 개선하면 좋을지 살펴보도록 하겠다!

🍩 원본 쿼리 정리

a. 사용자 정보 조회

SELECT
    u1_0.id,
    u1_0.first_today_tasks_completed_at,
    u1_0.created_at,
    u1_0.escape_badge_1,
    u1_0.escape_badge_aapjam,
    u1_0.escape_barely_badge_1,
    u1_0.escape_barely_badge_2,
    u1_0.escape_barely_badge_3,
    u1_0.first_create_study_count,
    u1_0.first_study_completed_at,
    u1_0.has_mass_baking_bread_badge,
    u1_0.has_preparing_opening_bakery,
    u1_0.inssa_boss_badge_1,
    u1_0.inssa_boss_badge_2,
    u1_0.is_onboarding_complete,
    u1_0.last_study_completed_date,
    u1_0.nickname,
    u1_0.platform,
    u1_0.platform_user_id,
    u1_0.user_point,
    u1_0.today_study_complete_count,
    u1_0.updated_at,
    u1_0.user_level
FROM users u1_0
WHERE u1_0.id = ?

b. 학기별 과목 조회

SELECT
    s1_0.id,
    s1_0.created_at,
    s1_0.motivation_message,
    s1_0.subject_name,
    s1_0.updated_at,
    s1_0.user_subject_id
FROM subject s1_0
JOIN user_subject us1_0
    ON us1_0.id = s1_0.user_subject_id
WHERE
    us1_0.user_id = ?
    AND us1_0.year = ?
    AND us1_0.semester = ?

c. 과목별 시험 정보 조회

SELECT
    e1_0.subject_id,
    e1_0.id,
    e1_0.created_at,
    e1_0.exam_date,
    e1_0.exam_name
FROM exam e1_0
WHERE e1_0.subject_id = ?

d. 미완료된 piece 개수 집계

  • 현재 날짜 이후 마감 기한:
SELECT
    COUNT(p1_0.id)
FROM piece p1_0
JOIN study s1_0
    ON s1_0.id = p1_0.study_id
JOIN exam e1_0
    ON e1_0.id = s1_0.exam_id
JOIN subject s2_0
    ON s2_0.id = e1_0.subject_id
JOIN user_subject us1_0
    ON us1_0.id = s2_0.user_subject_id
JOIN users u1_0
    ON u1_0.id = us1_0.user_id
WHERE
    s2_0.id = ?
    AND e1_0.id = ?
    AND u1_0.id = ?
    AND p1_0.is_finished = 0
    AND p1_0.deadline >= CURRENT_DATE
  • 현재 날짜 이전 마감 기한:
SELECT
    COUNT(p1_0.id)
FROM piece p1_0
JOIN study s1_0
    ON s1_0.id = p1_0.study_id
JOIN exam e1_0
    ON e1_0.id = s1_0.exam_id
JOIN subject s2_0
    ON s2_0.id = e1_0.subject_id
JOIN user_subject us1_0
    ON us1_0.id = s2_0.user_subject_id
JOIN users u1_0
    ON u1_0.id = us1_0.user_id
WHERE
    s2_0.id = ?
    AND e1_0.id = ?
    AND u1_0.id = ?
    AND p1_0.is_finished = 0
    AND p1_0.deadline < CURRENT_DATE
  • Hibernate에서 실행된 SQL 로그를 통해 데이터베이스 쿼리의 복잡도와 실행 횟수를 파악할 수 있었다.
  • 로그에서 여러 개의 SELECT 쿼리가 실행되고 있으며, 특히 count 쿼리가 여러 번 호출된 것이 확인된다. 이는 최적화의 여지가 있을 수 있음을 나타내고, 앞선 과제에 적었듯이 인덱스를 사용하면 개선될 여지가 있다!

 

🍩 개선할 여지가 있는 부분 !

  1. 인덱스 추가: 조인 및 조건 필드(user_id, year, semester, deadline)에 적절한 인덱스 설정.
  2. 페이징 적용: 반환 데이터의 양을 제한.
  3. 캐싱 도입: 고정된 데이터 또는 빈번히 조회되는 데이터에 대해 Redis 캐싱.
  4. 쿼리 실행 계획 분석: 복잡한 조인 및 조건 쿼리의 실행 계획을 분석하여 성능 최적화 여부 판단.

 

🥪 단일 요청에서 알 수 없는 사항들 !

  1. Wait Time: 로컬에서 진행했기 때문에 클라이언트 대기 시간을 분석할 수 없다 ㅠ
  2. 동시 요청 처리 성능: 단일 요청으로는 동시 사용자(VUser)가 많아졌을 때의 서버 성능(스케일링 여부, 병목 등)을 확인할 수 없다. (요청이 하나만 들어오기 때문에 ㅠㅠ )
  3. 시스템 전체 병목 분석: 예를 들어, 특정 API, 데이터베이스, 또는 네트워크가 병목인지 단일 요청 로그만으로는 판단하기 어렵다 !

 

🥪 추가로 해야 할 성능 테스트

  1. Wait Time 측정 추가:
    • Filter 또는 Interceptor를 통해 요청 시작 시간을 기록하여 Wait Time을 측정해야 한다.
  2. 동시 요청 성능 테스트:
    • JMeter 또는 Apache Bench와 같은 도구를 사용하여 동시 사용자 수를 점진적으로 늘리며 서버 성능을 분석할 예정이다.
    • 예: VUser 50 → 100 → 200 → 500 → 1000 방식으로 테스트.
  3. SQL 최적화 확인:
    • Hibernate 쿼리를 프로파일링하여 N+1 문제 또는 반복 쿼리 호출을 확인하고, 이를 최적화할 수 있다.

Metadata

Metadata

Assignees

Labels

3차docs 📃

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions