HikariCP 커넥션 풀 고갈 트러블 슈팅 (feat. 스레드 덤프)

테스팅 개요

 

위와 같은 서버 구조에서 알림 시스템을 구축하고 알림 전송 시스템의 생산자서버인 Main Server에 K6로 부하테스트를 수행했습니다.

 

테스트 목적

1. 본 테스트는 서버의 자원을 최대한으로 사용하여 알림 전송이 어느 정도의 TPS를 달성하는지를 측정하는 것 입니다.

 

2. 테스트를 통해 각종 지표를 분석하고 코드 수정이나 설정 변경을 통해  더 높은 TPS를 달성할 수 있는 지 탐색해보는 것 입니다.

 

3. 마지막으로 서버의 자원을 최대한으로 활용하지 않고 평이한 트래픽은 어느 정도로 처리가 가능한 지 측정하려 합니다.

 

K6 스크립트

• 30초 간 100명의 가상유저
• 1분 간 300명의 가상유저
• 1분 간 500명의 가상유저
• 개별 가상 사용자의 요청의 간격 2초

import http from "k6/http";
import { check, sleep } from "k6";

export const options = {
  stages: [
    { duration: "0.5m", target: 100 },
    { duration: "1m", target: 300 },
    { duration: "1m", target: 500 },
  ],
};

export default function () {
  const headers = {
    headers: {
      "Content-Type": "application/json",
      Authorization: `Bearer eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiIxIiwiaWF0IjoxNzM2MTY3MDkxLCJleHAiOjE3MzYxNzQyOTF9.9lYCIgWZ59oKmwQS5iWuUyMq5LAtuyDA-vCLx3MgRV7c6CyEB-1wOUaiefZSCX3mAAd2vg5vado1Gi5TCGh2gQ`,
    },
  };
  const payload = JSON.stringify({ minute: 15 });
  const res = http.post(
    "https://amorgakco.store/api/group-participants/groups/1/tardiness",
    payload,
    headers
  );
  check(res, {
    "status is 200": (r) => r.status === 200,
  });
  sleep(2); // 요청 간격
}

 

첫 시도 

K6 결과

 

요청을 5346개 중 27건은 실패했습니다.

 

TPS = 35

 

Thread Status : Main 서버

 

어떤 스레드가 어떤 이유로 timed-waiting 상태에 들어갔는지는 스레드 덤프를 떠봐야 알겠지만 최대 200개의 스레드가 timed-waiting 상태에 들어갔습니다.

 

HikariCP Connection Pool

 

빨간색 라인은 커넥션 풀에서 커넥션 획득을 대기하는 스레드들로 최대 200개까지 증가합니다.

 

자세한 스레드 상태 확인을 위해서 스레드 덤프를 분석해보려합니다.

 

jstack 명령어와 쉘스크립트 [스레드 덤프]

우선 GCP 콘솔에서 도커 컨테이너 내부로 들어갑니다.

 

sudo docker exec -it cc85cc0a4d7c bash

 

그 다음 jps 명령어로 Spring 프로세스의 PID를 알아내야합니다.

 

 

이제 jstack 명령어로 스레드 덤프를 떠야하는데 jstack 명령어는 실행 시점의 스레드 상태만을 알려주기 때문에

 

시간변화에 맞춰 추적하기가 어렵고 문제 상황에 타이밍을 맞춰 덤프를 떠야합니다.

 

그렇기 때문에 jstack을 주기적으로 실행할 수 있는 스크립트를 이용해야합니다.

 

jstackSeries.sh/jstackSeries.sh at master · cqsupport/jstackSeries.sh

 

위에 있는 깃헙 저장소에서 스크립트를 복사해 주기적으로 스레드덤프를 생성할 수 있습니다.

 

#!/bin/bash

if [ $# -eq 0 ]; then
    echo >&2 "Usage: jstackSeries <pid> [ <count> [ <delay> ] ]"
    echo >&2 "    Defaults: count = 10, delay = 1 (seconds)"
    exit 1
fi

pid=$1          # required
count=${2:-10}  # defaults to 10 times
delay=${3:-1}   # defaults to 1 second

# Directory to store jstack dumps
output_dir="jstack_dumps_$pid"
mkdir -p $output_dir

while [ $count -gt 0 ]
do
    # Generate jstack dump and save it to the output directory
    jstack $pid > "$output_dir/jstack.$pid.$(date +%s.%N)"
    sleep $delay
    let count--
    echo -n "."
done

echo
echo "Jstack dumps completed. Compressing files into a ZIP archive..."

# Compress all files in the output directory
zip_file="jstack_dumps_$pid.zip"
zip -r $zip_file $output_dir

if [ $? -eq 0 ]; then
    echo "Compression successful: $zip_file"
    # Optionally, clean up the output directory after compression
    rm -rf $output_dir
else
    echo "Compression failed."
fi

 

저는 생성된 스레드 덤프를 압축하는 코드까지 추가해서 실행했습니다.

주의점
컨테이너 내부에서는 vi 나 zip 을 실행할 수 없습니다. 호스트에 설치 됐다 하더라도 컨테이너는 다른 컴퓨터나 마찬가지이기 때문입니다.
sudo apt-get install zip
sudo apt-get install vi
로 설치해줘야합니다.

 

저는 저장소 파일 이름과 동일하게 jstackSeries.sh 으로 파일을 생성했고

./jstackSeries.sh 119 15 10 # PID, 스레드 덤프 개수, Delay

 

10초간격으로 15개의 스레드 덤프를 생성해 zip파일을 생성했습니다.

 

생성된 zip은 cp같은 명령어로 파일을 복사할 수 없고 docker cp 명령어를 이용해 컨테이너->호스트로 전송해야합니다.

docker cp [container name]:[container 내부 경로] [host 파일경로]

 

그 다음 GCP 콘솔에서 파일을 로컬로 다운로드했습니다.

 

Fastthread.io

fastthread.io

 

fastthread.io는 스레드 덤프 파일을 분석해주는 사이트입니다. 일반 txt파일, raw 데이터, zip 파일 들을 지원하기 때문에 zip으로 묶어 분석을 시작했습니다.

 

스레드 덤프 분석

fastthread.io

 

 

189개의 스레드에서 문제가 발견됐는데 그라파나로 모니터링한 결과와 일치합니다.

stackTrace:
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(
java.base@17.0.5/Native Method
)
- parking to wait for 
<0x00000000c4ef5478>
 (a java.util.concurrent.SynchronousQueue$TransferQueue)
at java.util.concurrent.locks.LockSupport.parkNanos(
java.base@17.0.5/LockSupport.java:252
)
at java.util.concurrent.SynchronousQueue$TransferQueue.transfer(
java.base@17.0.5/SynchronousQueue.java:704
)
at java.util.concurrent.SynchronousQueue.poll(
java.base@17.0.5/SynchronousQueue.java:903
)
at com.zaxxer.hikari.util.ConcurrentBag.borrow(
ConcurrentBag.java:151
)
at com.zaxxer.hikari.pool.HikariPool.getConnection(
HikariPool.java:162
)
at com.zaxxer.hikari.pool.HikariPool.getConnection(
HikariPool.java:144
)
at com.zaxxer.hikari.HikariDataSource.getConnection(
HikariDataSource.java:127
)

 

HikariCP에서 커넥션을 가져오려 큐에 접근했지만 풀에 커넥션이 고갈돼 parkNanos()로 스레드가 잠들어 있습니다.

 

이러한 Stack Trace는 189개의 모든 스레드에서 관찰됐고 원인이 DB 커넥션 풀 고갈에 있다는 것을 확인했습니다.

parkNanos()는 자바의 concurrent 패키지에 있는 SynchronousQueue 에서 사용하는 LockSupport 내부 함수입니다.

 

자바 내부에 내장된 모니터락(syncronize 키워드)보다 훨씬 유연하게 락을 잡거나 락 경합을 제어할 수 있는 자바의 락 기술입니다.

 

두 번째 시도 : OSIV = false

먼저 OSIV를 의심해봤습니다.

 

OSIV가 기본 값으로 켜져있게 되면 트랜잭션이 끝나고도 영속성 컨텍스트는 열려있고 커넥션도 풀에 반환하지 않습니다.

 

현재 테스트 로직엔 트랜잭션이 끝나고 별도로 Lazy Loading으로 객체 탐색을 하지 않기 때문에 해당 옵션을 false로 변경해보기로 했습니다.

 

OSIV를 false로 변경해봤지만 지표의 변화는 없었고 커넥션 풀 고갈을 해결하지는 못했습니다.

 

OSIV가 켜져 있는 것이 아무런 영향도 없다고 할 순 없지만 근본 원인이 OSIV가 아니라고 판단할 수 있습니다.

 

세 번째 시도 : Main 서버와 MySQL 분리

Main서버와 MySQL은 같은 서버 인스턴스에서 도커 컴포즈로 실행 중 이었습니다.

 

MySQL도 내부에선 포그라운드 스레드와 백그라운드 스레드로 쿼리를 처리하기 때문에

 

코어가 한정된 서버 내부에서 많은 스레드(MySQL, Main Server)가 생성돼 트랜잭션을 수행하는 스레드의 실행 기회를 뺐어 커넥션 풀을 고갈 시키지 않았을까 의심했습니다.

 

서버 인스턴스를 새롭게 확보하고 해당 서버에서 MySQL를 기동해봤지만 지표에는 별 다른 차이점은 없었습니다.

 

네 번째 시도 : 트랜잭션을 얇게 만들기

@Transactional
public void tardy(final Long groupId, final Long memberId,
    final TardinessRequest tardinessRequest) {
    final GroupParticipant groupParticipant = getGroupParticipant(groupId, memberId);
    final Group group = groupService.getGroupWithHost(groupId);
    notificationPublisherFacade.send(NotificationCreator.tardy(
        groupParticipant.getMember(),
        group.getHost(),
        group,
        tardinessRequest.minute()
    ));

 

위 쿼리가 알림을 전송하는 서비스 레이어 코드이고 발생하는 쿼리는 아래와 같습니다.

 

- 그룹원 Select

- 그룹 Select

- notificationPublisherFacde.send() 내부에서 알림 객체 Insert

 

총 3개의 쿼리가 한 트랜잭션 내부에서 발생합니다. 쿼리의 개수를 줄여 볼 수 있다면 트랜잭션의 부피를 줄일 수 있을 것이라 생각했습니다.

 

그룹 Select는 그룹원을 Select할 때 Join을 통해 함께 가져올 수 있어 쿼리를 한 번 줄일 수 있습니다.

 

@Query(
    "select p from GroupParticipant p join fetch p.group g join fetch g.host join fetch p.member where p.group.id"
        + " = :groupId and p.member.id = :memberId")
Optional<GroupParticipant> findByGroupAndMember(final Long groupId, final Long memberId);

public void tardy(final Long groupId, final Long memberId,
    final TardinessRequest tardinessRequest) {
    final GroupParticipant groupParticipant = getGroupParticipant(groupId, memberId);
    Group group = groupParticipant.getGroup();
    notificationPublisherFacade.send(NotificationCreator.tardy(
        groupParticipant.getMember(),
        group.getHost(),
        group,
        tardinessRequest.minute()
    ));

 

네 번째 시도 : 결과

K6

 

쿼리 하나를 줄였을 뿐인데 영향이 매우 큽니다. 17585개의 요청을 처리했고 TPS는 119로 측정됐습니다.

 

HikariCP Connection Pool

 

Pending Thread(빨간색 라인) 또한 189개에서 35개로 감소했습니다.

 

Main Server Thread Status

 

HikariCP에서 Connection을 기다리는 스레드들도 약 120개로 기존 200개보다 80개 가량 감소했습니다.

 

다섯 번째 시도 : 

 

부하 테스트 결론

서버가 2분30초라는 시간 동안 순간적으로 몰리는 트래픽을 죽지않고 약 120 TPS까지는 처리가 가능한 것을 확인했습니다.

 

물론 위 시나리오에서 Main 서버의 CPU 사용률은 98%에 가깝게 측정됐고 MySQL 서버의 경우 85%까지 측정됐습니다.

이는 운영 환경에선 분명한 장애 상황입니다. 119 TPS를 운영 환경에서 받아내려해서는 당연히 안됩니다.

 

위 시나리오 상에서 더 긴 시간 부하를 준다면 하드웨어 스펙을 높이거나 수평적으로 서버를 확장해 트래픽을 분산해 CPU 사용률을 낮춰야합니다.

 

다음 글에선 평이한 수준의 트래픽은 어느 정도인지를 측정해보려합니다.