LY DB tech blog
Published on

Sharded Cluster에서 Secondary Read 시 읽기 지연 문제

Authors
  • avatar
    Name
    박붕어
    Twitter

개요

LINE에서는 Album, Shopping, Sticker 등에서 메인 저장소로 사용되는 큰 규모의 MongoDB Sharded Cluster를 운영하고 있습니다. 큰 규모의 MongoDB를 운영하면서 다양한 문제들과 마주치는데요. 한국에서도 MongoDB가 많이 사용되고 있긴 하지만, 아직 한국어로 된 자료들은 많이 부족한 것 같습니다. 그러다 보니 운영하면서 겪는 이슈나 문제들을 찾을 때 항상 참고할 만한 자료가 많이 부족하다고 느끼고 있습니다. 그래서 LINE에서 MongoDB를 운영하면서 겪은 이슈나 문제들에 대해 기술적인 내용과 인사이트 등을 공유하면 좋을 것 같다고 생각합니다. 

 

그리고 첫 번째 주제는 Sharded Cluster에서 Secondary Read를 사용했을 때 읽기가 지연되는 이슈에 대해 공유하고자 합니다.

문제 발견 

어느 날, 개발자분께서 Sharded Cluster의 query timeout 발생량이 증가했다고 문의를 주셨습니다. LINE의 주요 서비스 중 하나이다 보니, Query 시 Timeout을 500ms 정도로 설정하고 사용하는 서비스였는데요.
문제를 확인해 보니, Secondary Read를 수행하는 쿼리들에서 평소보다 많은 Slow Query가 발생한 것을 확인할 수 있었습니다.

 

저희 팀은 원인을 찾기 위해 분석을 시작했는데요. 분석 결과를 통해 도출한 이슈의 특징은 다음과 같았습니다. 

  1. Secondary Read를 사용하는 Query에서만 Slow Query가 발생하고 있었습니다. Primary Read 또는 Write를 수행하는 쿼리는 Slow Query가 발생하지 않았습니다. 
  2. MongoDB 서버의 리소스 ( CPU, Memory, Network, Disk ) 사용량은 특별히 평소와 같았고 이상이 없었습니다. 
  3. 하지만, Slow Query Count의 수가 눈에 띄게 증가했습니다. 

개발자분과 소통하면서 확인한 결과, 사실 Slow Query count가 증가한 이유는 서비스 트래픽이 전 일 대비 2배가량 증가했기 때문인 것으로 확인되었습니다. 요청이 2배 많아지면서 Slow Query가 증가했던 것이였습니다.

 

하지만 해당 이슈를 조사하면서 이상한 점이 있었습니다. 
Sharded Cluster에서 Primary Read를 수행할 때는 Slow Query가 발생하지 않지만 Secondary Read를 사용하는 경우 Slow Query가 발생했던 것입니다. 그래서 조금 더 해당 이슈를 분석하고 원인을 찾고자 했습니다. 왜 이런 일이 발생을 했던 것인지 더 자세히 과정을 살펴보겠습니다. 

Stale Config Error Log

MongoDB에서는 쿼리 수행시간이 임계치를 초과하는 경우 Slow Query Log가 mongod.log 또는 mongos.log에 남게 됩니다. 
우선 Slow Query가 발생했기 때문에, 해당 로그를 살펴보았습니다. 

I  QUERY    [conn1114827] Unable to establish remote cursors - {error: StaleConfig{ ns: "###.####", vReceived: Timestamp(43679, 211), vReceivedEpoch: ObjectId('617a6dd284baa66f8f02f008'), vWanted: Timestamp(0, 0), vWantedEpoch: ObjectId('000000000000000000000000') }: epoch mismatch detected for ###.####, the collection may have been dropped and recreated, numActiveRemotes: 9} 
I  QUERY    [conn1115532] Unable to establish remote cursors - {error: StaleConfig{ ns: "###.####", vReceived: Timestamp(43679, 211), vReceivedEpoch: ObjectId('617a6dd284baa66f8f02f008'), vWanted: Timestamp(0, 0), vWantedEpoch: ObjectId('000000000000000000000000') }: epoch mismatch detected for ###.####, the collection may have been dropped and recreated, numActiveRemotes: 11}
I  QUERY    [conn1114773] Unable to establish remote cursors - {error: StaleConfig{ ns: "###.####", vReceived: Timestamp(43679, 211), vReceivedEpoch: ObjectId('617a6dd284baa66f8f02f008'), vWanted: Timestamp(0, 0), vWantedEpoch: ObjectId('000000000000000000000000') }: epoch mismatch detected for ###.####, the collection may have been dropped and recreated, numActiveRemotes: 11}
I  SH_REFR  [ConfigServerCatalogCacheLoader-44621] Refresh for collection ###.#### from version 43679|226||7a6dd284baa66f8f02f008 to version 43679|229||7a6dd284baa66f8f02f008 took 503 ms
I  CONNPOOL [TaskExecutorPool-0] Connecting to #####
I  COMMAND  [conn1114827] command ###.#### command: find { ...., $readPreference: { mode: "secondaryPreferred" } } nShards:10 cursorExhausted:1 numYields:0 nreturned:100 reslen:5618 protocol:op_msg 2499ms
I  COMMAND  [conn1114773] command ###.#### command: find { ...., $readPreference: { mode: "secondaryPreferred" } } nShards:12 cursorExhausted:1 numYields:0 nreturned:100 reslen:5618 protocol:op_msg 1921ms
I  COMMAND  [conn1115532] command ###.#### command: find { ...., $readPreference: { mode: "secondaryPreferred" } } nShards:12 cursorExhausted:1 numYields:0 nreturned:100 reslen:5618 protocol:op_msg 1362ms

로그를 봤을 때 Slow Query 근처에서 Stale Config Error라는 로그를 발견할 수 있었습니다.
해당 로그를 보면

  1. connection에서 Stale Config Error가 발생합니다.
  2. ConfigServerCatalogCacheLoader가 Chunk의 버전을 업데이트합니다.
  3. Stale Config Error를 뱉은 connection에서 Slow Query가 발생합니다.

이러한 패턴을 확인할 수 있었습니다. 

 

그냥 단순히 해당 쿼리가 수행시간이 오래 걸리는 무거운 쿼리였기 때문에, Slow Query로 발생한 것은 아니였을까요? 해당 쿼리가 무거운 쿼리였는지 확인해 보기 위해 로그를 수집하여 저장하고 있는 OpenSearch Cluster에서 확인을 해봤습니다. 그 결과 Slow Query로 남은 쿼리들은 최대 5,810ms까지 쿼리가 수행되고 있었는데요.

서비스에서 OLTP 성으로 수행하고 있는 쿼리인데 해당 쿼리의 Slow Query 수행시간은 5,810ms ~ 1,001ms까지 다양했습니다. ( 1,000ms 이하는 Slow Query Log에 기록되지 않아 잡히지 않습니다. )

또한 해당 쿼리가 거의 6초에 육박하는 수행시간을 가질 정도로 무거운 쿼리라고는 생각이 들지 않았기 때문에, 해당 패턴에 문제가 있는 것 같다고 생각을 하게 되었습니다. 

 

그리고 이 패턴은 Slow Query가 발생하는 서버들에서 공통적으로 발견되었습니다. 
저는 이러한 패턴에서 문제가 발생하고 있는 것 같아 Stale Config Error가 무엇인지 조금 더 살펴보았습니다. 

Stale Config Error에 대해 알아보자. 

 Stale Config Error에 대해 알아보기 전에 Sharded Cluster 구성에서 mongos가 어떻게 동작하는지에 대한 정보는 mongos는 어떻게 Target Shard를 빠르게 찾을 수 있을까? 글을 참고 부탁드립니다. 

Stale Config Error 란?

mongos는 클라이언트로부터의 요청을 빠르게 라우팅하기 위해서 어떤 샤드에 어떤 데이터가 위치하고 있는지에 대한 정보인 Routing table cache를 가지고 있습니다. 
모든 종류의 캐시와 마찬가지로, mongos가 가지고 있는 Routing table cache는 데이터 조회 속도를 올려주지만 Cache fault가 발생할 경우 문제가 발생할 수 있습니다. 
MongoDB 에서는 Chunk Migration, Chunk Split으로 인해 chunks 컬렉션의 데이터가 변경되었을 때, mongos에게 Routing table cache를 갱신하라는 요청을 따로 보내지 않습니다.
Chunk Migration이나 Chunk Split이 발생하면 Chunk의 위치나 범위가 달라졌지만, mongos는 달라진 Chunk의 변경사항을 알 수 없습니다. 

 

Stale Config Exception은 이 때 발생합니다. mongos에서 Routing table을 조회해 데이터가 있는 샤드로 요청을 보냈지만 해당 샤드에 데이터가 위치하고 있지 않은 경우 샤드는 mongos에게 Stale Config Exception을 돌려주게 됩니다.

Stale Config Exception을 받지 않는 경우 Stale Config Exception을 받은 경우

Stale Config Exception을 받게 되면 mongos는  Config server로 부터 메타데이터를 가져와 자신의 Routing table을 갱신하고 데이터가 위치하는 샤드로 다시 요청을 보내 필요한 데이터를 가져옵니다.  

Stale Config Exception 의 문제 

결론적으로 데이터가 위치한 샤드에 다시 요청을 보내 데이터를 가져오기 때문에 데이터의 정합성에는 문제가 없지만, Stale Config Error가 발생한 경우 Read Latency가 길어질 수 있습니다. 

Stale Config Exception을 받지 않는 경우 Stale Config Exception을 받는 경우

Stale Config Exception이 발생하지 않는 쿼리는 mongos와 샤드 간의 한 번의 통신이면 데이터를 가져올 수 있지만 Stale config Exception이 발생하는 쿼리의 경우 mongos와 샤드 간의 Round trip이 두 번 발생하기 때문에, 일반적인 쿼리보다 쿼리 수행시간이 오래걸리게 됩니다.
위의 그림처럼, 각 컴포넌트 간의 Network Latency를 50ms로 가정할 때, 일반 쿼리는 200ms가 걸리지만 Stale Config Exception이 발생한 쿼리는 400ms가 걸리게 됩니다.  
mongos와 샤드 간의 거리, mongos와 Config Server 간의 거리가 멀어질수록 쿼리 수행시간은 더욱 길어지게 됩니다. 이로 인해 클라이언트에서는 한 번의 쿼리 수행이 오래 걸리게 됩니다. 

 

하지만, 이슈가 발생한 MongoDB의 구성에서는 mongos와 샤드 간 Network Latency는 평균 5ms 이하로 측정되었습니다. 
Stale Config Error가 발생해서 쿼리를 수행하는데 2번의 Round trip을 수행하지만 그렇게 되더라도 쿼리 수행시간이 5,810ms까지 걸릴 것 같다고는 생각되지 않았습니다. 
또한, Slow Query Log에 남는 쿼리 수행시간은 mongos가 요청을 받고, 요청에 대한 데이터를 전달해 주기까지의 시간이기 때문에 클라이언트 ↔ mongos 간 네트워크 지연시간을 포함하지 않는 시간입니다. 

 

그래서 단순히 Stale Config Error가 문제의 원인일 것이라고는 납득하기 조금 힘들었습니다. 
그럼 왜 이렇게 Slow Query가 발생했던 것일까요?? 

Secondary의 지연 문제   

 해당 이슈의 답은 다음 MongoDB 오픈소스의 JIRA Ticket에서 찾을 수 있었습니다.

https://jira.mongodb.org/browse/SERVER-67078

SERVER-67078

 

 

다음 티켓의 내용을 정리해보면 

  1. Chunk Split, Chunk Migration으로 인해 Chunk 데이터의 변경이 생기면 Primary가 Config server의 Chunk 메타데이터를 갱신합니다. 
  2. 이때, 작업이 원자적이지 않기 때문에 refresh flag를 true로 변경하고 작업을 시작합니다. 
  3. Secondary는 refresh flag가 true → false로 변경될 때까지 읽기를 대기합니다. 즉, Secondary 멤버는 변경된 Chunk 메타데이터 ( Stale Config )가 갱신될 때 까지 쿼리를 지연시킵니다. 
  4. 하지만 데이터의 유입이 많아 Chunk Split이 빈번하게 발생하는 경우 Secondary가 대기하는 동안 Primary에서 Chunk Split이 발생하는 경우 refresh flag가 다시 true로 변경되기 때문에 Secondary는 계속 변경을 기다리게 됩니다. 

결론적으로, Chunk Split이 빈번하게 발생하여 연속적으로 발생하는 경우, Secondary가 계속 대기하는 현상이 발생할 수 있다는 것입니다. 

 

이로써 다음 두 가지에 대한 원인이 분명해졌는데요. 

  1. Primary에서는 읽기 지연이 발생하지 않았습니다. : Primary는 Stale Config에 의해 지연이 발생하지 않습니다. Chunk Split 또는 Chunk Migration 발생 시 변경된 Config를 수정하고 Config server에 갱신을 요청하기만 합니다. 
  2. 쿼리 최대 수행시간이 5,810 ms까지 걸렸습니다. : Chunk Split이 빈번하게 발생하는 경우, 이론상으로는 Secondary가 무한정 기다릴 수 있게 됩니다. 대기하는 시간이 길어질수록 쿼리 수행시간이 늦어지게 됩니다. 

실질적인 개선 방안 

해당 문제를 개선하기 위해서는 다음 3가지 방식을 고려해 볼 수 있을 것 같습니다.

  1. Chunk Size를 64MB(default)에서 128MB로 변경하여 Chunk Split 횟수를 줄입니다. 
  2. readPreference를 PrimaryPreferred로 사용하여 문제를 해결합니다. 
  3. MongoDB의 버전을 5.0.4, 4.4.11, 4.2.18, 4.0.28 이상의 버전으로 업그레이드하여 Chunk Split 횟수를 줄이거나 6.0.3 이상의 버전으로 업그레이드하여 문제를 해결합니다. 

각각의 방식에는 장단점들이 존재하고 다른 시간과 비용이 들어갈 것으로 예상됩니다. 
특히, LINE의 MongoDB 팀에서는 큰 규모의 Sharded Cluster를 운영하고 있어 간단해 보이는 일도 많은 시간과 비용이 들어가는 경우가 있기 때문에 각 방안에 대해 신중하게 검토 후 적용해야합니다. 

결론 

서비스 트래픽의 증가로 Slow Query 발생 빈도가 증가한 단순한 문제로 보였지만, 문제의 원인을 분석하는 과정에서 Sharded Cluster + Secondary Read를 사용하는 경우의 이슈가 될만한 부분을 발견할 수 있었습니다. 
추후 MongoDB Sharded Cluster 사용 시에는 Secondary Read를 사용할 때 이러한 문제가 있다는 것을 충분히 고려하고 사용할 수 있을 것 같습니다. 

6.0 버전 이하의 Sharded Cluster를 운영 중이시면서, Secondary Read를 사용하시는 경우에 원인을 알 수 없는 Read Latency의 증가나 Slow Query Count의 증가가 있다면 Secondary의 Stale Config 지연 문제를 의심해 볼 수 있을 것 같습니다. 
그리고 같은 이슈가 발생한다면 앞서 말씀드린 개선 방식을 통해 문제를 해결해 보시는 것은 어떨까요? 

 

긴 글 읽어주셔서 감사합니다.