스트레스 테스트 (feat.connection pool)

nestjs, postgresql, typeorm, artillery

어쩌다가

내가 만든 서버가 어느정도의 성능인지 정확하게 판단할 수 있는 성능지표같은게 있으면 좋겠다.
하지만 예외상황과 각각의 환경들과 목표, 분석 방법 등등 다양한 방법으로 인해 명확한 성능 수준을 측정하기 어려운거같다.
뭐 응애인 내가 판단하기엔 너무 이른거 같고 일단 타임아웃이 발생하지 않는 한계선까지 서버를 몰아붙인 상태에서 레이턴시라도 줄여보자 했다.

간지나는그래프를쓰고싶어서 Jmeter나 Ngrinder를 사용해볼까 하고 이것저것 설정하다 또 하루를 날려먹었고
딱히 node.js에 특화된 테스트툴도 아니라서 그냥 원래 사용하던 artillery을 사용하기로 했다.
부캠 프로젝트 때 겉 핥기 수준으로만 해봤는데 이번엔 테스트 후 성능 개선까지 진행해보고자 했다.

테스트 환경 설정

테스트하기 앞서 artillery 실행에 필요한 yaml을 작성해줘야한다. 파일명은 원하는대로 작성하면 된다.

# loadtest.yaml

config:
  plugins:
    publish-metrics:
      - reportFile: './report.html'
  target: {서버주소}
  phases:
    - duration: 300 # 몇초간
      arrivalRate: 50 # 초당 생성할 가상 유저
      name: Warm up
scenarios: # 각 가상 유저가 실행할 시나리오(각 요청의 밀도)
  - name: User logs in and makes authenticated request
    flow:
      - post:
          url: '/api/auth/login'
          json:
            email: "test@test.com"
            password: "1234"
          capture: # 로그인 후 발급받은 토큰 캡쳐
            json: '$.token'
            as: 'authToken'
      - get:
          url: '/api/user/list-all'
          headers:
            Authorization: 'Bearer {{ authToken }}' # 요청 헤더에 캡쳐한 토큰 추가
      - get:
          url: '/api/user/list?search=random'
          headers:
            Authorization: 'Bearer {{ authToken }}'
      - get:
          url : '/api/user/list?search=sponsor'
          headers:
            Authorization: 'Bearer {{ authToken }}'
      - get:
          url : '/api/user/list?search=sponsored'
          headers:
            Authorization: 'Bearer {{ authToken }}'
      - get:
          url : '/api/user/list?search=allSponsored'
          headers:
            Authorization: 'Bearer {{ authToken }}'

그리고 터미널에서 해당 루트로 이동한 다음다 artillery를 실행해주면 설정 값에 따라 테스트가 시작된다

artillery run --output test-run-report.json loadtest.yaml

Load test 1

일단 타임아웃이 발생하지 않는 한계치를 알아내기위해 duration 은 60sec로 고정하고 arrivalRate 를 점차 늘려나갔다.

여담으로 원래 EC2에 배포된 서버에서 테스트 예정이였는데, 프로젝트 종료시점에서 갑자기 RDS 커넥션 이슈가 생겨서 로컬에서 진행하게 되었다..
aws를 공부하지않고 맨땅에 헤딩한 결과랄까 ㅎㅎ.. 이 번 프로젝트 문서화가 끝나면 aws부터 다시 공부해야한다..

arrivalRate : 70 으로 테스트한 결과

초당 70의 가상 유저(4200명)를 생성하고, 각 유저는 시나리오(총 25200번 요청)를 실행한다. 이 때 시나리오에서 DB에 전달되는 쿼리는 11개이므로 데이터베이스엔 분당 46200 번의 쿼리가 실행된다.

errors.ETIMEDOUT: .............................................................. 277
http.codes.200: ................................................................ 20169
http.codes.201: ................................................................ 4200
http.downloaded_bytes: ......................................................... 19726167
http.request_rate: ............................................................. 343/sec
http.requests: ................................................................. 24646
http.response_time:
  min: ......................................................................... 5
  max: ......................................................................... 9999
  mean: ........................................................................ 4437.9
  median: ...................................................................... 4147.4
  p95: ......................................................................... 8692.8
  p99: ......................................................................... 9047.6
http.responses: ................................................................ 24369
vusers.completed: .............................................................. 3923
vusers.created: ................................................................ 4200
vusers.created_by_name.User logs in and makes authenticated request: ........... 4200
vusers.failed: ................................................................. 277
vusers.session_length:
  min: ......................................................................... 156.4
  max: ......................................................................... 41889.9
  mean: ........................................................................ 26083.8
  median: ...................................................................... 27181.5
  p95: ......................................................................... 39747.5
  p99: ......................................................................... 41369.7

테스트 결과를 보면 엉망진창인데, 데이터베이스엔 딱히 무리가 가지 않았으니 서버가 과부화 상태가 되어서 타임아웃과 지연이 발생하는걸 확인할 수 있다.

arrivalRate 를 60으로 낮춰보자

http.codes.200: ................................................................ 18000
http.codes.201: ................................................................ 3600
http.downloaded_bytes: ......................................................... 17452303
http.request_rate: ............................................................. 346/sec
http.requests: ................................................................. 21600
http.response_time:
  min: ......................................................................... 4
  max: ......................................................................... 1901
  mean: ........................................................................ 817.8
  median: ...................................................................... 871.5
  p95: ......................................................................... 1380.5
  p99: ......................................................................... 1436.8
http.responses: ................................................................ 21600
vusers.completed: .............................................................. 3600
vusers.created: ................................................................ 3600
vusers.created_by_name.User logs in and makes authenticated request: ........... 3600
vusers.failed: ................................................................. 0
vusers.session_length:
  min: ......................................................................... 121
  max: ......................................................................... 8431.3
  mean: ........................................................................ 4915.3
  median: ...................................................................... 5272.4
  p95: ......................................................................... 7865.6
  p99: ......................................................................... 8186.6

타임아웃이 발생하지 않고 모든 요청에 응답을 성공했다.
그럼 대략적인 서버의 최대 성능은 분당 3600명을 수용하고 초당 345의 요청을 처리하며 평균 817.5의 속도로 응답한다고 볼 수 있다.

커넥션 풀링

문제는 지금부터였다. 더 이상 쿼리를 최적화 할 수 없는 상태였고 인덱스 설정도 잘 되어있다면 로드밸런싱을 제외한 성능 개선의 다른 방법이 없을까하고 고민했다.

시나리오에 사용된 요청들은 단일 쿼리를 사용중이였다. 그나마 페이징이 필요한 요청에는 findAndCount 메서드를 사용해서 두 번의 쿼리를 쓰는정도.

  async getUsers(page: number, limit: number): Promise<ResponseUserListDto> {
    const [users, totalCount] = await this.userRepository.findAndCount({
      skip: (page - 1) * limit,
      take: limit,
      order: {
        createdAt: "DESC",
      },
    });
    const totalPage: number = Math.ceil(totalCount / limit);

    return { users: plainToInstance(GetUserListDto, users), totalPage, currentPage: page };
  }

그러다 커넥션풀링을 사용하면 성능향상에 도움되지 않을까 생각했다.
부하테스트에서 분당 3600명을 수용했기에 커넥션 옵션을 넉넉하게 4500으로 잡아주었다.
typeorm은 내부적으로 커넥션 풀링을 지원한다.

export const typeOrmConfig: TypeOrmModuleOptions = {
  type: "postgres",
  host: process.env.DB_HOST,
  port: Number(process.env.DB_PORT),
  username: process.env.DB_USER_NAME,
  password: String(process.env.DB_PASSWORD),
  database: process.env.DB_NAME,
  entities: [User, Post, Comment, Like, Payments, AccountHistory],
  synchronize: true,
  migrations: ["dist/migration/*.js"],
  migrationsTableName: "migrations",
  extra: {
    max: 4500, // 풀에 유지할 최대 커넥션 수
    connectionTimeoutMillis: 5000,
  },
  ...
}

Load test 2

커넥션 풀링을 설정하고 동일한 조건에서 다시 테스트를 진행해보자.
좀 더 정확한 집계를 위해 duration 을 300으로 증가시키고 커넥션 풀링을 적용하기 전과 후를 비교했다

// 적용 전

http.codes.200: ................................................................ 90000
http.codes.201: ................................................................ 18000
http.downloaded_bytes: ......................................................... 87240246
http.request_rate: ............................................................. 360/sec
http.requests: ................................................................. 108000
http.response_time:
  min: ......................................................................... 3
  max: ......................................................................... 861
  mean: ........................................................................ 115
  median: ...................................................................... 39.3
  p95: ......................................................................... 528.6
  p99: ......................................................................... 645.6
http.responses: ................................................................ 108000
vusers.completed: .............................................................. 18000
vusers.created: ................................................................ 18000
vusers.created_by_name.User logs in and makes authenticated request: ........... 18000
vusers.failed: ................................................................. 0
vusers.session_length:
  min: ......................................................................... 77.7
  max: ......................................................................... 3897.9
  mean: ........................................................................ 698.5
  median: ...................................................................... 223.7
  p95: ......................................................................... 3134.5
  p99: ......................................................................... 3752.7

// 적용 후
errors.Failed capture or match: ................................................ 12
http.codes.200: ................................................................ 89744
http.codes.201: ................................................................ 17988
http.codes.500: ................................................................ 208	// 서버에러발생
http.downloaded_bytes: ......................................................... 87022853
http.request_rate: ............................................................. 360/sec
http.requests: ................................................................. 107940
http.response_time:
  min: ......................................................................... 2
  max: ......................................................................... 5774	// 과부화로 인한 응답 지연
  mean: ........................................................................ 224.9
  median: ...................................................................... 70.1
  p95: ......................................................................... 804.5
  p99: ......................................................................... 907
http.responses: ................................................................ 107940
vusers.completed: .............................................................. 17988
vusers.created: ................................................................ 18000
vusers.created_by_name.User logs in and makes authenticated request: ........... 18000
vusers.failed: ................................................................. 12
vusers.session_length:
  min: ......................................................................... 78.3
  max: ......................................................................... 13290.7
  mean: ........................................................................ 1354.5
  median: ...................................................................... 314.2
  p95: ......................................................................... 4867
  p99: ......................................................................... 6569.8

커넥션풀링을 적용 후 오히려 성능저하와 에러 가 발생되었다.

커넥션 사이즈를 설정한 기준은, 최대 세션길이와 초당 처리해야할 쿼리로 어림잡아 계산했었다.
그럼 항상 알맞은 크기의 풀이 대기중이여서 처리속도가 빨라졌어야하지만 오히려 느려졌기에, 풀이 너무 많아서 서버 성능을 저하시켰나 생각했지만 원인은 다른 곳에 있었다.

Less is more

출처: [번역] 커넥션 풀 사이즈에 대하여 Copyright © Jinwoo's Blog

PostgreSQL - 데이터베이스 커넥션 개수 최적의 처리량을 위해서는 활성화된 커넥션의 개수가 ((core_count 2) + effective_spindle_count) 정도여야 한다는 것이 수 년에 걸쳐 입증된 공식이다. 하이퍼쓰레딩이 활성화되었더라도 코어 개수에 HT 쓰레드를 포함시키면 안 된다. 활성화된 데이터가 전부 캐쉬되어있다면 효율적인 스핀들 개수는 0입니다. 그리고 캐쉬 적중률이 감소할수록 점차 실제 스핀들의 개수에 가까워지게 됩니다. ... 다만, 해당 공식이 SSD에 얼마나 적절하게 적용될 수 있는지에 대한 분석은 아직 없습니다.

자세한 설명은 해당 링크에서 아주 자세히 잘 정리되어 있다.

PostgreSQL은 디스크와 네트워크에 대한 접근 시간을 고려하여, CPU 코어 개수의 두 배에 해당하는 크기로 설정하는 것을 권장한다고 한다. 이는 CPU 코어가 병렬로 작업을 처리할 수 있도록 하여 성능을 최적화하는 데 도움이 되고 데이터베이스에 동시에 접근할 수 있는 수가 증가하면서 블록된 커넥션의 수가 증가할 가능성이 있으므로, 이를 고려하여 effective_spindle_count를 추가로 더해준다.

결론은 '풀이 얼마나 커야할까'로만 생각하고 CPU와 쓰레드의 동작 방식을 이해하지 못한 채 무작정 커넥션 풀 사이즈의 크기만 키운게 화근이였다.

Final load test

이제 해당 공식에 맞게 커넥션 풀 사이즈를 변경하고 테스트를 진행한다.
Connection Pool Size = (core_count * 2) + effective_spindle_count
postgres 컨테이너는 4코어로 실행중인 상태였는데, 해당 공식에 맞춘다면 현재 가장 최적의 커넥션 풀 사이즈는 9가 된다. (모든 상황에 적용되는 공식이 아님을 주의)

// 변경 전

errors.Failed capture or match: ................................................ 12
http.codes.200: ................................................................ 89744
http.codes.201: ................................................................ 17988
http.codes.500: ................................................................ 208	// 서버에러발생
http.downloaded_bytes: ......................................................... 87022853
http.request_rate: ............................................................. 360/sec
http.requests: ................................................................. 107940
http.response_time:
  min: ......................................................................... 2
  max: ......................................................................... 5774	// 과부화로 인한 응답 지연
  mean: ........................................................................ 224.9
  median: ...................................................................... 70.1
  p95: ......................................................................... 804.5
  p99: ......................................................................... 907
http.responses: ................................................................ 107940
vusers.completed: .............................................................. 17988
vusers.created: ................................................................ 18000
vusers.created_by_name.User logs in and makes authenticated request: ........... 18000
vusers.failed: ................................................................. 12
vusers.session_length:
  min: ......................................................................... 78.3
  max: ......................................................................... 13290.7
  mean: ........................................................................ 1354.5
  median: ...................................................................... 314.2
  p95: ......................................................................... 4867
  p99: ......................................................................... 6569.8

// 변경 후

http.codes.200: ................................................................ 90000
http.codes.201: ................................................................ 18000
http.downloaded_bytes: ......................................................... 87228881
http.request_rate: ............................................................. 353/sec
http.requests: ................................................................. 108000
http.response_time:
  min: ......................................................................... 3
  max: ......................................................................... 250
  mean: ........................................................................ 37.2
  median: ...................................................................... 25.8
  p95: ......................................................................... 90.9
  p99: ......................................................................... 147
http.responses: ................................................................ 108000
vusers.completed: .............................................................. 18000
vusers.created: ................................................................ 18000
vusers.created_by_name.User logs in and makes authenticated request: ........... 18000
vusers.failed: ................................................................. 0
vusers.session_length:
  min: ......................................................................... 78.1
  max: ......................................................................... 1068.5
  mean: ........................................................................ 230.8
  median: ...................................................................... 198.4
  p95: ......................................................................... 459.5
  p99: ......................................................................... 837.3

공식에 맞게 커넥션 풀 사이즈를 조절하고 난 후 눈에 띄게 성능이 좋아진걸 확인할 수 있다.

	공식 적용 전	공식 적용 후
초당 응답 개수	360	353
평균 레이턴시	70.1	25.8
최대 레이턴시	5774	250
평균 세션길이	314.2	198.4
최대 세션길이	13290.7	1068.5

짤막후기

아무리 짱구를 굴려도 더 이상 최적화할 곳을 찾지 못했을 때 커넥션 사이즈가 생각났었다 포폴에 쓸게없어 무조건 찾아야해
기본으로 설정되어 있던 커넥션 사이즈가 100 이였기에 단순히 서버에 무리가 가지 않을 정도로 사이즈만 키우면 성능이 개선되겠구나 생각했다가 예상치 못한 테스트 결과에 뇌정지가 왔었다.

붙잡고 물어볼 사람이 없었다곤 하나 조금만 더 자세히 서치 했더라면 금방 해결할 수 있던 문제를 며칠이나 질질 끌게되었다.
개발을 하면 할 수록 CS, C언어 또는 데이터베이스의 근본적인 지식이 필요한 이슈를 자주만나게 되고, 그마저도 시원하게 해결되진 않고 또 다른 의문을 남긴다.
그렇다고 저 거대한 녀석들을 전부 짚고 넘어가기엔 시간도, 머리도 허락해줄리가 없다ㅋㅋㅋ.. 물고 늘어져야할 꼬리가 점점 늘어가는 기분이라, 앞으로 알아가야 할 방대한 지식에 압도당하는 기분마져 든다. 하다보면 언젠가는 되겠지😗
다른거 없이 스오플과 공식문서로만 개발했던 찐 개발자분들이 존경스러워지는 순간입니다..