[MongoDB] API 응답시간이 7초라고요..??

소셜 로그인 토큰 검증을 위해서 프록시 서버 -> 인증 서버로 호출을 하고 있다.
개발 후에 클라분들께 전달 드렸는데, 프록시 서버에서 해당 API 를 호출하자 인증서버 -> 프록시 서버로 응답하는 시간이 5초를 초과하여 타임아웃 에러가 발생했다.

카카오 토큰 검증 API는 1.5초 이내인데, 애플 토큰 검증 API 응답요청만 7초

애플 토큰 검증이 다른 소셜 로그인과 달리 추가적으로 JWT를 생성하고 파싱하는 부분에서 시간이 많이 들거라 예상했다.

이제 로그로 각 메서드 실행시간을 찍어서 병목지점을 찾아보자.

메서드 명	소요 시간
애플 인증 서버 호출	758ms
JWT 생성 및 파싱	23ms
몽고 DB 에서 데이터 조회	5522ms

예상과 달리 병목지점은 조회 메서드였다.

조회하는 쿼리인데 5.5초라니

개발환경이라 데이터가 4855593 개 밖에 없는데, 이상하다.

스키마 대략적으로 다음과 같아요

{
  "_id": "uuid",
  "providers": {
    "kakao": {
    			"id" : "kakao_id",
                "pushNotificationAgreed" : true
    },
    "apple": {						// 새로 추가된 필드
    			"id" : "apple_id",
    }
  },
}

기존에 카카오 간편가입 밖에 없었지만, 애플 회원가입이 생기면서 providers 하위 필드에 apple 이 추가되었다.

쿼리 실행 계획 쿼리와 결과

db.SocialLoginInformation.find({"providers.apple.id":"431493942143"}).explain("executionStats")

... "executionStages": {"stage": "COLLSCAN", "nReturned": "0", "executionTimeMillisEstimate": "10364.051"}}

인덱스를 타지 않고, 풀스캔하고 있는 것을 알 수 있다.

COLLSCAN: 전체 스캔
IXSCAN: 인덱스 스캔

그럼 카카오 필드 조회 쿼리는 왜 1초인가

... "executionStages": {"stage": "IXSCAN", "nReturned": "0", "executionTimeMillisEstimate": "16.125", "indexName": "providers.kakao.id_1_createdAt_1", "direction": "forward"}}

컬렉션에 대한 인덱스 조회 결과 kakao.id 에 인덱스가 걸려있어 같은 조회 쿼리지만 시간 소요가 적었다. 당연하게도 인덱스를 타는 것을 볼 수 있다.

컬렉션에 대한 인덱스 조회 쿼리

db.SocialLoginInformation.getIndexes()

애플에도 인덱스를 걸어주자

인덱스 추가 쿼리

db.SocialLoginInformation.createIndex({"providers.apple.id": 1}, { sparse: true, unique: true })

인덱스 삭제 쿼리

db.SocialLoginInfo.dropIndex("인덱스 이름")

정리

• 쿼리 실행 계획을 확인하자.(특히 mongoDB 처럼 필드 추가가 자유로운 Document DB 에서는)
• 해당 키로 자주 조회하면, 인덱스를 걸어주자.
• 몽고 DB 쿼리 실행 계획

  db.SocialLoginInformation.find({"providers.apple.id":"431493942143"}).explain("executionStats")

• 몽고 DB 컬렉션에 대한 인덱스 조회

  db.SocialLoginInformation.getIndexes()

• 몽고 DB 인덱스 추가 쿼리

  db.SocialLoginInformation.createIndex({"providers.apple.id": 1}, { sparse: true, unique: true })