[PUBG Analyzer] 몽고db 인덱스 설정을 통한 성능 개선

성능 저하 발생

현재 나와 친구 총 4명이 내 서비스를 사용 중이다. 최근 특정 페이지의 응답속도가 느려졌다고 느껴졌고, 다른 사용자에게도 물어본 결과 똑같이 느려졌다고 느끼고 있었다. 그 페이지를 처음 조회할 때는 외부 API를 호출하고 결과를 DB에 저장하기 때문에 오래 걸렸다. 그다음 요청은 이미 DB에 저장된 데이터를 조회해 오는 것이기 때문에 빠르게 응답받을 수 있었다. 하지만, 이미 DB에 저장된 데이터를 불러옴에도 불구하고 응답 속도가 너무 느렸다!

 

부하 테스트

성능 개선 전 기준을 잡기 위해 nGrinder와 jMeter, scouter로 측정을 진행했다. 실제 배포 환경에는 telemetry(게임 로그 데이터)데이터 베이스에 380만 건, match 데이터베이스에 922건의 데이터가 존재한다.

 

Vuser 99, 60 sec test

 

Vuser 100 테스트에서 scouter TPS의 경우 4가 되지 않았고, nGrinder를 보면 테스트가 정상적으로 진행되지 못하는 것 같았다.

응답 속도 또한 scouter 그래프 y축을 뚫고 넘어가 버렸다.

 

Vuser10, 60sec test

그래서 Vuser를 10으로 낮추고 다시 진행한 결과 TPS 1.2라는 처참한 수치를 만나게 되었다.

 

병목 지점 파악

먼저 어디서 병목 지점이 생기는지 파악하기로 했다. 테스트는 로컬 환경에서 진행하였고, telemetry(게임 로그 데이터) 데이터베이스에는 약 54만 개, match 데이터베이스에는 약 480개가 저장되어 있다.

 

비즈니스 로직

 쿼리 조회, API 요청, DB 저장, 응답 객체 생성과 같은 기타 로직이 있었고, API 요청 및 DB 저장은 이미 저장된 데이터를 조회해 오는 경우이기 때문에 용의 선상에서 제외했다. 그다음 의심되는 범인은 쿼리 조회였다. 설마 조회 때문에 성능이 저하될까 의심했다. (지금까지 적은 데이터만 다뤄봤기 때문에)

 

DB 조회

DB 조회 목록은 아래와 같다.

 

1. 게임 로그 데이터 존재 확인

2. 매치 조회

3. 필요한 세부 로그 조회 (1~2번)

 

게임 로그 데이터 존재 확인

게임 로그 데이터 존재 확인을 위해 실행되는 쿼리는 로그를 통해 확인할 수 있었다.

DEBUG [http-nio-8080-exec-1] org.mongodb.driver.protocol.command      -- Sending command '{"aggregate": "telemetries", "pipeline": [{"$match": {"matchId": "6976c06e-71f8-46e2-9998-105f27436fe6"}}, {"$limit": 1}, {"$group": {"_id": 1, "n": {"$sum": 1}}}], "cursor": {}, "$db": "pubg-analyzer", "lsid": {"id": {"$binary": {"base64": "SegCp+mHSW6jrXl7DQfoGw==", "subType": "04"}}}}' with request id 9 to database pubg-analyzer on connection [connectionId{localValue:3, serverValue:92}] to server localhost:27017

 

위 쿼리의 실행 계획을 살펴본 결과

db.telemetries.aggregate(
    [{"$match": {"matchId": "6976c06e-71f8-46e2-9998-105f27436fe6"}}, {"$limit": 1}, {"$group": {"_id": 1, "n": {"$sum": 1}}}]
).explain()

 

{
  "winningPlan": {
    "stage": "LIMIT",
    "limitAmount": 1,
    "inputStage": {
      "stage": "COLLSCAN",
      "filter": {
        "matchId": {
          "$eq": "6976c06e-71f8-46e2-9998-105f27436fe6"
        }
      },
      "direction": "forward"
    }
  }
}

 

COLLSCAN 즉, 전체 스캔을 하고 있다는 것을 확인했다.

 

그리고 실행 속도는 444.91ms로 조회 속도치고 느리다고 생각됐다.

DEBUG [http-nio-8080-exec-1] org.mongodb.driver.protocol.command      -- Execution of command with request id 9 completed successfully in 444.91 ms on connection [connectionId{localValue:3, serverValue:92}] to server localhost:27017

 

매치 조회

매치 조회의 경우 _id 값을 조회하고 있었고, 당연하게도 인덱스를 사용하고 있었다. (IDHACK)

DEBUG [http-nio-8080-exec-1] org.mongodb.driver.protocol.command      -- Sending command '{"find": "matches", "filter": {"_id": "6976c06e-71f8-46e2-9998-105f27436fe6"}, "limit": 1, "singleBatch": true, "$db": "pubg-analyzer", "lsid": {"id": {"$binary": {"base64": "SegCp+mHSW6jrXl7DQfoGw==", "subType": "04"}}}}' with request id 10 to database pubg-analyzer on connection [connectionId{localValue:3, serverValue:92}] to server localhost:27017

db.matches.find(
    {"_id": "6976c06e-71f8-46e2-9998-105f27436fe6"}
).limit(1).explain()

"winningPlan": {
  "stage": "IDHACK"
}

 

인덱스를 사용하기 때문에 실행 속도 또한 1.86ms로 빨랐다.

DEBUG [http-nio-8080-exec-1] org.mongodb.driver.protocol.command      -- Execution of command with request id 10 completed successfully in 1.86 ms on connection [connectionId{localValue:3, serverValue:92}] to server localhost:27017

 

세부 로그 조회

킬별 데미지 로그를 조회해 오는 엔드포인트로 테스트하였고, 이 경우 세부 로그 조회를 두 번 실행한다. 각각 182.88ms, 160.30ms 가 소요되었다. 역시 인덱스는 사용되고 있지 않았다.

 

(서버 로그, 쿼리 생략...)

 

DB 조회 외 기타 로직

쿼리 조회 후 응답을 위한 기타 프로세스와 객체 생성에도 꽤 오랜 시간이 걸리지 않을까 걱정했지만 , 전체 응답 시간 930ms 중 DB 조회 시간 444.91ms, 1.86ms, 182.88ms, 160.30ms를 뺀 나머지 140.05ms 밖에 걸리지 않았다.

 

정리하자면, 전체 응답 시간 930ms 중 DB 조회에 789.95ms, 기타 140.05ms가 소요되었고 DB 조회 시간은 전체 응답 시간의 85%를 차지하였다.

 

인덱스 설정

telemetry DB 조회에 사용되는 matchId로 인덱스를 생성해 주었다.

db.telemetries.createIndex({matchId: 1})

 

그 결과, 게임 로그 데이터 존재 확인 및 세부 로그 조회 시 인덱스를 사용하고 있는 것이 확인되었다. (IXSCAN)

db.telemetries.aggregate(
    [{"$match": {"matchId": "6976c06e-71f8-46e2-9998-105f27436fe6"}}, {"$limit": 1}, {"$group": {"_id": 1, "n": {"$sum": 1}}}]
).explain()

"winningPlan": {
  "stage": "LIMIT",
  "limitAmount": 1,
  "inputStage": {
    "stage": "IXSCAN",
    "keyPattern": {
      "matchId": 1
    },
    "indexName": "matchId_1",
    "isMultiKey": false,
    "multiKeyPaths": {
      "matchId": []
    },
    "isUnique": false,
    "isSparse": false,
    "isPartial": false,
    "indexVersion": 2,
    "direction": "forward",
    "indexBounds": {
      "matchId": ["[\"6976c06e-71f8-46e2-9998-105f27436fe6\", \"6976c06e-71f8-46e2-9998-105f27436fe6\"]"]
    }
  }
}

 

서버 로그를 통해서도 그 결과를 확인할 수 있었다.

 

게임 로그 데이터 존재 확인에 20.56ms로 기존의 약 5% 수준으로 단축되었고, 세부 로그 조회는 각각 182.88ms, 160.30ms가 걸리던 것을 63.26ms, 31.26ms로 약 35%, 20%로 단축했다.

 

	인덱스 설정 전	인덱스 설정 후
게임 로그 데이터 존재 확인	444.91ms	20.56ms	5%
세부 로그 조회	343.18ms (182.88 + 160.30)	94.52ms (63.26 + 31.26)	28%

 

전체 응답 시간은 기존 930ms에서 241ms로 26% 수준으로 단축했다.

 

다시 부하 테스트

Vuser 10, 60 sec test

 

Vuser 100, 60sec test

 

TPS가 1~3 수준에서 약 40 정도까지 올라왔고, jMeter 평균 응답 속도도 777ms에서 141ms로 빨라졌다.

 

	개선 전	개선 후
TPS	1 ~ 3	40	2000%
평균 응답 속도	777	141	18%

 

 

마무리

RDMS의 경우 막연하게 자주 조회되는 컬럼으로 인덱스를 설정해 왔고, 그래서 인덱스 설정 전후 성능 비교를 해본 경험이 없었다. 또한 많은 데이터를 다루지 않아 효과가 미미했을 것이다. 하지만, 이 프로젝트를 통해 약 380만 건이라는 많은 데이터를 다뤄볼 수 있게 되었고, 덕분에 인덱스의 효과를 체감할 수 있었다.

 조회 성능을 개선하자고 무분별하게 인덱스를 생성해서는 안된다. 인덱스 생성은 곧 용량 및 데이터 삽입 성능 저하로 연결되니 주의하자.